Merge remote-tracking branch 'origin/feat/rsync-debug' into dev

# Conflicts:
#	RSYNC_COMPAT.md
#	src/client/client_cli.c
#	src/client/usage.c
#	src/shared/log.h
#	src/shared/protocol.c

src/shared/chunk.c

@@ -290,7 +290,7 @@ Chunk* chunk_deserialize(Data* data, bool use_metadata) {
 }
 
 Data* chunk_compress(Chunk* chunk, int compression_level, bool use_metadata) {
-  log_message(LOG_LEVEL_DEBUG, "Starting to compress chunk");
+  log_debug_message(LOG_DEBUG_PACK, "Starting to compress chunk");
   Data* serialized = chunk_serialize(chunk, use_metadata);
   if (serialized == NULL)
     return NULL;
@@ -298,7 +298,7 @@ Data* chunk_compress(Chunk* chunk, int compression_level, bool use_metadata) {
   data_destroy(serialized);
   if (compressed == NULL)
     return NULL;
-  log_message(LOG_LEVEL_DEBUG, "Chunk successfully compressed");
+  log_debug_message(LOG_DEBUG_PACK, "Chunk successfully compressed");
   return compressed;
 }
 

src/shared/compression.c

@@ -28,7 +28,7 @@ bool compression_should_skip(const char* path) {
 }
 
 Data* data_compress(Data* data_to_compress, int compression_level) {
-  log_message(LOG_LEVEL_DEBUG, "Starting to compress data");
+  log_debug_message(LOG_DEBUG_UTIL, "Starting to compress data");
   size_t dst_size = ZSTD_compressBound(data_to_compress->size);
   Data* compressed_data = data_create_empty(dst_size);
   if (compressed_data == NULL)
@@ -66,8 +66,8 @@ Data* data_compress(Data* data_to_compress, int compression_level) {
   compressed_data->size = output.pos;
   ZSTD_freeCCtx(cctx);
 
-  log_message(LOG_LEVEL_DEBUG, "Data succesfully compressed from %zu to %zu",
-              data_to_compress->size, compressed_data->size);
+  log_debug_message(LOG_DEBUG_UTIL, "Data succesfully compressed from %zu to %zu",
+                    data_to_compress->size, compressed_data->size);
   return compressed_data;
 }
 
@@ -75,7 +75,7 @@ Data* data_decompress_limited(Data* compressed_data, size_t maximum_size) {
   if (!compressed_data || (!compressed_data->data && compressed_data->size != 0) ||
       maximum_size == 0)
     return NULL;
-  log_message(LOG_LEVEL_DEBUG, "Start to decompress data");
+  log_debug_message(LOG_DEBUG_UTIL, "Start to decompress data");
   unsigned long long dst_size =
       ZSTD_getFrameContentSize(compressed_data->data, compressed_data->size);
   if (ZSTD_isError(dst_size)) {
@@ -155,7 +155,7 @@ Data* data_decompress_limited(Data* compressed_data, size_t maximum_size) {
   uncompressed_data->size = output.pos;
   ZSTD_freeDCtx(dctx);
 
-  log_message(LOG_LEVEL_DEBUG, "Decompressed data successfully");
+  log_debug_message(LOG_DEBUG_UTIL, "Decompressed data successfully");
   return uncompressed_data;
 }
 

src/shared/log.c

@@ -7,6 +7,7 @@
 
 static const char* log_level_strings[] = {"DEBUG", "INFO", "WARN", "ERROR"};
 static LogLevel current_log_level = LOG_LEVEL_WARNING;
+static uint32_t current_debug_flags = 0;
 static FILE* log_fp = NULL;
 static _Thread_local bool eight_bit_output;
 static LogStderrMode stderr_mode = LOG_STDERR_ERRORS;
@@ -15,6 +16,14 @@ void set_log_level(LogLevel level) {
   current_log_level = level;
 }
 
+void set_log_debug_flags(uint32_t flags) {
+  current_debug_flags = flags;
+}
+
+uint32_t get_log_debug_flags(void) {
+  return current_debug_flags;
+}
+
 void log_set_file(FILE* fp) {
   log_fp = fp;
 }
@@ -71,6 +80,27 @@ void log_message(LogLevel log_level, const char* format, ...) {
   }
 }
 
+void log_debug_message(LogDebugFlag flag, const char* format, ...) {
+  if (current_log_level > LOG_LEVEL_DEBUG || !(current_debug_flags & flag))
+    return;
+
+  time_t now = time(NULL);
+  struct tm t;
+  if (!localtime_r(&now, &t))
+    return;
+
+  va_list args;
+  va_start(args, format);
+  write_message(stdout, LOG_LEVEL_DEBUG, t, format, args);
+  va_end(args);
+
+  if (log_fp) {
+    va_start(args, format);
+    write_message(log_fp, LOG_LEVEL_DEBUG, t, format, args);
+    va_end(args);
+  }
+}
+
 void log_perror(const char* context) {
   log_message(LOG_LEVEL_ERROR, "%s: %s", context, strerror(errno));
 }

src/shared/log.h

@@ -3,13 +3,25 @@
 
 #include <stdio.h>
 #include <stdbool.h>
+#include <stdint.h>
 
 typedef enum { LOG_LEVEL_DEBUG, LOG_LEVEL_INFO, LOG_LEVEL_WARNING, LOG_LEVEL_ERROR } LogLevel;
 typedef enum { LOG_STDERR_ERRORS, LOG_STDERR_ALL } LogStderrMode;
 
+typedef enum {
+  LOG_DEBUG_IO = 1u << 0,
+  LOG_DEBUG_PROTO = 1u << 1,
+  LOG_DEBUG_PACK = 1u << 2,
+  LOG_DEBUG_UTIL = 1u << 3,
+  LOG_DEBUG_ALL = (1u << 4) - 1,
+} LogDebugFlag;
+
 void log_message(LogLevel log_level, const char* message, ...);
 void log_perror(const char* context);
 void set_log_level(LogLevel level);
+void set_log_debug_flags(uint32_t flags);
+uint32_t get_log_debug_flags(void);
+void log_debug_message(LogDebugFlag flag, const char* message, ...);
 void log_set_file(FILE* fp);
 void log_set_8_bit_output(bool enabled);
 bool log_get_8_bit_output(void);

src/shared/protocol.c

@@ -200,7 +200,7 @@ static int deadline_remaining_ms(const struct timespec* deadline) {
 bool protocol_send_n_data(ProtocolSession* session, const void* data, size_t data_size) {
   if (!data && data_size != 0)
     return false;
-  log_message(LOG_LEVEL_DEBUG, "    Sending n Data: %zu", data_size);
+  log_debug_message(LOG_DEBUG_IO, "    Sending n Data: %zu", data_size);
   if (!session)
     return false;
   int fd = session->write_fd;
@@ -244,12 +244,12 @@ bool protocol_send_n_data(ProtocolSession* session, const void* data, size_t dat
     if (session->ssl)
       wait_events = POLLOUT;
   }
-  log_message(LOG_LEVEL_DEBUG, "    Send n Data: %zu", total_bytes_send);
+  log_debug_message(LOG_DEBUG_IO, "    Send n Data: %zu", total_bytes_send);
   return true;
 }
 
 bool protocol_receive_n_data(ProtocolSession* session, void* data, size_t data_size) {
-  log_message(LOG_LEVEL_DEBUG, "    Receiving n Data: %zu", data_size);
+  log_debug_message(LOG_DEBUG_IO, "    Receiving n Data: %zu", data_size);
   if (!session)
     return false;
   int fd = session->read_fd;
@@ -303,7 +303,7 @@ bool protocol_receive_n_data(ProtocolSession* session, void* data, size_t data_s
     if (session->ssl)
       wait_events = POLLIN;
   }
-  log_message(LOG_LEVEL_DEBUG, "    Received n Data: %zu", total_bytes_received);
+  log_debug_message(LOG_DEBUG_IO, "    Received n Data: %zu", total_bytes_received);
   return true;
 }
 
@@ -344,9 +344,7 @@ bool protocol_send_str(ProtocolSession* session, const char* data) {
     return false;
   if (!protocol_send_n_data(session, data, size))
     return false;
-  char* escaped = output_escape(data, session->eight_bit_output);
-  log_message(LOG_LEVEL_DEBUG, "Send String: %s", escaped ? escaped : "<allocation failed>");
-  free(escaped);
+  log_debug_message(LOG_DEBUG_PROTO, "Send String: %s", data);
   return true;
 }
 
@@ -374,9 +372,7 @@ char* protocol_receive_str(ProtocolSession* session) {
   }
   data[size] = '\0';
   session->total_allocated_bytes += size + 1;
-  char* escaped = output_escape(data, session->eight_bit_output);
-  log_message(LOG_LEVEL_DEBUG, "Received String: %s", escaped ? escaped : "<allocation failed>");
-  free(escaped);
+  log_debug_message(LOG_DEBUG_PROTO, "Received String: %s", data);
   return data;
 }
 
@@ -390,7 +386,7 @@ bool protocol_send_data(ProtocolSession* session, const Data* data) {
     return false;
   if (!protocol_send_n_data(session, data->data, data_size))
     return false;
-  log_message(LOG_LEVEL_DEBUG, "Send %lld data", data_size);
+  log_debug_message(LOG_DEBUG_PROTO, "Send %lld data", data_size);
   return true;
 }
 
@@ -420,7 +416,7 @@ Data* protocol_receive_data_limited(ProtocolSession* session, unsigned long long
     return NULL;
   }
   session->total_allocated_bytes += allocation_size;
-  log_message(LOG_LEVEL_DEBUG, "Received %lld data", size);
+  log_debug_message(LOG_DEBUG_PROTO, "Received %lld data", size);
   Data* result = data_create(data, (size_t)size);
   if (!result) {
     session->total_allocated_bytes -= allocation_size;
@@ -437,28 +433,28 @@ Data* protocol_receive_data(ProtocolSession* session) {
 bool protocol_send_int(ProtocolSession* session, int data) {
   if (!protocol_send_n_data(session, &data, sizeof(int)))
     return false;
-  log_message(LOG_LEVEL_DEBUG, "Send Int: %d", data);
+  log_debug_message(LOG_DEBUG_PROTO, "Send Int: %d", data);
   return true;
 }
 
 bool protocol_receive_int(ProtocolSession* session, int* data) {
   if (!protocol_receive_n_data(session, data, sizeof(int)))
     return false;
-  log_message(LOG_LEVEL_DEBUG, "Received Int: %d", *data);
+  log_debug_message(LOG_DEBUG_PROTO, "Received Int: %d", *data);
   return true;
 }
 
 bool protocol_send_status(ProtocolSession* session, Status status) {
   if (!protocol_send_n_data(session, &status, sizeof(Status)))
     return false;
-  log_message(LOG_LEVEL_DEBUG, "Send Status: %s", status_to_string(status));
+  log_debug_message(LOG_DEBUG_PROTO, "Send Status: %s", status_to_string(status));
   return true;
 }
 
 bool protocol_receive_status(ProtocolSession* session, Status* status) {
   if (!protocol_receive_n_data(session, status, sizeof(Status)))
     return false;
-  log_message(LOG_LEVEL_DEBUG, "Received Status: %s", status_to_string(*status));
+  log_debug_message(LOG_DEBUG_PROTO, "Received Status: %s", status_to_string(*status));
   return true;
 }