Improve logging.

src/protocols/rdp/debug.h

@@ -58,7 +58,7 @@
 #define GUAC_RDP_DEBUG(level, fmt, ...)                           \
     do {                                                          \
         if (DEBUG >= level)                                       \
-            fprintf(stderr, "@@ DEBUG @@ %s:%d: %s(): " fmt "\n", \
+            fprintf(stderr, "%s:%d: %s(): " fmt "\n", \
                     __FILE__, __LINE__, __func__, __VA_ARGS__);   \
     } while (0);
 

src/protocols/rdp/guac_rdpdr/rdpdr_fs_messages.c

@@ -41,6 +41,7 @@
 #include "compat/winpr-stream.h"
 #endif
 
+#include <inttypes.h>
 #include <guacamole/pool.h>
 #include <errno.h>
 
@@ -89,6 +90,12 @@ void guac_rdpdr_fs_process_create(guac_rdpdr_device* device,
             desired_access, file_attributes,
             create_disposition, create_options);
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i] "
+             "desired_access=0x%x, file_attributes=0x%x, "
+             "create_disposition=0x%x, create_options=0x%x, path=\"%s\"",
+             file_id, desired_access, file_attributes, create_disposition,
+             create_options, path);
+
     /* If an error occurred, notify server */
     if (file_id < 0) {
         guac_client_log_error(device->rdpdr->client,
@@ -143,6 +150,9 @@ void guac_rdpdr_fs_process_read(guac_rdpdr_device* device,
     Stream_Read_UINT32(input_stream, length);
     Stream_Read_UINT64(input_stream, offset);
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i] length=%i, offset=%" PRIu64,
+             file_id, length, (uint64_t) offset);
+
     /* Read no more than size of buffer */
     if (length > sizeof(buffer))
         length = sizeof(buffer);
@@ -184,6 +194,9 @@ void guac_rdpdr_fs_process_write(guac_rdpdr_device* device,
     Stream_Read_UINT64(input_stream, offset);
     Stream_Seek(input_stream, 20); /* Padding */
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i] length=%i, offset=%" PRIu64,
+             file_id, length, (uint64_t) offset);
+
     /* Attempt write */
     bytes_written = guac_rdp_fs_write((guac_rdp_fs*) device->data, file_id,
             offset, Stream_Pointer(input_stream), length);
@@ -214,6 +227,8 @@ void guac_rdpdr_fs_process_close(guac_rdpdr_device* device,
     wStream* output_stream;
     guac_rdp_fs_file* file;
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i]", file_id);
+
     /* Get file */
     file = guac_rdp_fs_get_file((guac_rdp_fs*) device->data, file_id);
     if (file == NULL)
@@ -362,8 +377,10 @@ void guac_rdpdr_fs_process_file_info(guac_rdpdr_device* device, wStream* input_s
 
 void guac_rdpdr_fs_process_set_volume_info(guac_rdpdr_device* device, wStream* input_stream,
         int file_id, int completion_id) {
+
     /* STUB */
-    guac_client_log_info(device->rdpdr->client, "STUB: %s", __func__);
+    GUAC_RDP_DEBUG(2, "[file_id=%i] STUB", file_id);
+
 }
 
 void guac_rdpdr_fs_process_set_file_info(guac_rdpdr_device* device,
@@ -418,6 +435,8 @@ void guac_rdpdr_fs_process_device_control(guac_rdpdr_device* device,
     wStream* output_stream = guac_rdpdr_new_io_completion(device,
             completion_id, STATUS_INVALID_PARAMETER, 4);
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i] IGNORED", file_id);
+
     /* No content for now */
     Stream_Write_UINT32(output_stream, 0);
 
@@ -427,8 +446,10 @@ void guac_rdpdr_fs_process_device_control(guac_rdpdr_device* device,
 
 void guac_rdpdr_fs_process_notify_change_directory(guac_rdpdr_device* device,
         wStream* input_stream, int file_id, int completion_id) {
+
     /* STUB */
-    guac_client_log_info(device->rdpdr->client, "STUB: %s", __func__);
+    GUAC_RDP_DEBUG(2, "[file_id=%i] STUB", file_id);
+
 }
 
 void guac_rdpdr_fs_process_query_directory(guac_rdpdr_device* device, wStream* input_stream,
@@ -465,6 +486,9 @@ void guac_rdpdr_fs_process_query_directory(guac_rdpdr_device* device, wStream* i
 
     }
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i] initial_query=%i, dir_pattern=\"%s\"",
+             file_id, initial_query, file->dir_pattern);
+
     /* Find first matching entry in directory */
     while ((entry_name = guac_rdp_fs_read_dir((guac_rdp_fs*) device->data,
                     file_id)) != NULL) {
@@ -538,7 +562,9 @@ void guac_rdpdr_fs_process_query_directory(guac_rdpdr_device* device, wStream* i
 
 void guac_rdpdr_fs_process_lock_control(guac_rdpdr_device* device, wStream* input_stream,
         int file_id, int completion_id) {
+
     /* STUB */
-    guac_client_log_info(device->rdpdr->client, "STUB: %s", __func__);
+    GUAC_RDP_DEBUG(2, "[file_id=%i] STUB", file_id);
+
 }
 

src/protocols/rdp/guac_rdpdr/rdpdr_fs_messages_dir_info.c

@@ -47,18 +47,23 @@
 #include "rdpdr_messages.h"
 #include "rdp_fs.h"
 #include "rdp_status.h"
+#include "debug.h"
 #include "unicode.h"
 
 void guac_rdpdr_fs_process_query_directory_info(guac_rdpdr_device* device,
         const char* entry_name, int file_id, int completion_id) {
+
     /* STUB */
-    guac_client_log_info(device->rdpdr->client, "STUB: %s", __func__);
+    GUAC_RDP_DEBUG(2, "[file_id=%i (entry_name=\"%s\")] STUB", file_id, entry_name);
+
 }
 
 void guac_rdpdr_fs_process_query_full_directory_info(guac_rdpdr_device* device,
         const char* entry_name, int file_id, int completion_id) {
+
     /* STUB */
-    guac_client_log_info(device->rdpdr->client, "STUB: %s", __func__);
+    GUAC_RDP_DEBUG(2, "[file_id=%i (entry_name=\"%s\")] STUB", file_id, entry_name);
+
 }
 
 void guac_rdpdr_fs_process_query_both_directory_info(guac_rdpdr_device* device,
@@ -78,6 +83,8 @@ void guac_rdpdr_fs_process_query_both_directory_info(guac_rdpdr_device* device,
     if (file == NULL)
         return;
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i (entry_name=\"%s\")]", file_id, entry_name);
+
     output_stream = guac_rdpdr_new_io_completion(device, completion_id,
             STATUS_SUCCESS, 4 + 69 + 24 + utf16_length + 2);
 
@@ -109,7 +116,9 @@ void guac_rdpdr_fs_process_query_both_directory_info(guac_rdpdr_device* device,
 
 void guac_rdpdr_fs_process_query_names_info(guac_rdpdr_device* device,
         const char* entry_name, int file_id, int completion_id) {
+
     /* STUB */
-    guac_client_log_info(device->rdpdr->client, "STUB: %s", __func__);
+    GUAC_RDP_DEBUG(2, "[file_id=%i (entry_name=\"%s\")] STUB", file_id, entry_name);
+
 }
 

src/protocols/rdp/guac_rdpdr/rdpdr_fs_messages_file_info.c

@@ -41,6 +41,7 @@
 #include "compat/winpr-stream.h"
 #endif
 
+#include <inttypes.h>
 #include <guacamole/pool.h>
 
 #include "rdpdr_messages.h"
@@ -65,6 +66,8 @@ void guac_rdpdr_fs_process_query_basic_info(guac_rdpdr_device* device, wStream*
     if (file == NULL)
         return;
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i]", file_id);
+
     output_stream = guac_rdpdr_new_io_completion(device, completion_id,
             STATUS_SUCCESS, 40);
 
@@ -78,8 +81,6 @@ void guac_rdpdr_fs_process_query_basic_info(guac_rdpdr_device* device, wStream*
     /* Reserved field must not be sent */
 
     svc_plugin_send((rdpSvcPlugin*) device->rdpdr, output_stream);
-    GUAC_RDP_DEBUG(2, "Sent STATUS_SUCCESS for completion_id=%i",
-            completion_id);
 
 }
 
@@ -95,6 +96,8 @@ void guac_rdpdr_fs_process_query_standard_info(guac_rdpdr_device* device, wStrea
     if (file == NULL)
         return;
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i]", file_id);
+
     if (file->attributes & FILE_ATTRIBUTE_DIRECTORY)
         is_directory = TRUE;
 
@@ -111,8 +114,6 @@ void guac_rdpdr_fs_process_query_standard_info(guac_rdpdr_device* device, wStrea
     /* Reserved field must not be sent */
 
     svc_plugin_send((rdpSvcPlugin*) device->rdpdr, output_stream);
-    GUAC_RDP_DEBUG(2, "Sent STATUS_SUCCESS for completion_id=%i",
-            completion_id);
 
 }
 
@@ -127,6 +128,8 @@ void guac_rdpdr_fs_process_query_attribute_tag_info(guac_rdpdr_device* device,
     if (file == NULL)
         return;
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i]", file_id);
+
     output_stream = guac_rdpdr_new_io_completion(device, completion_id,
             STATUS_SUCCESS, 12);
 
@@ -137,8 +140,6 @@ void guac_rdpdr_fs_process_query_attribute_tag_info(guac_rdpdr_device* device,
     /* Reserved field must not be sent */
 
     svc_plugin_send((rdpSvcPlugin*) device->rdpdr, output_stream);
-    GUAC_RDP_DEBUG(2, "Sent STATUS_SUCCESS for completion_id=%i",
-            completion_id);
 
 }
 
@@ -159,6 +160,8 @@ void guac_rdpdr_fs_process_set_rename_info(guac_rdpdr_device* device,
     guac_rdp_utf16_to_utf8(Stream_Pointer(input_stream),
             destination_path, filename_length/2);
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i] destination_path=\"%s\"", file_id, destination_path);
+
     /* Perform rename */
     result = guac_rdp_fs_rename((guac_rdp_fs*) device->data, file_id,
             destination_path);
@@ -184,6 +187,8 @@ void guac_rdpdr_fs_process_set_allocation_info(guac_rdpdr_device* device,
     /* Read new size */
     Stream_Read_UINT64(input_stream, size); /* AllocationSize */
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i] size=%" PRIu64, file_id, (uint64_t) size);
+
     /* Truncate file */
     result = guac_rdp_fs_truncate((guac_rdp_fs*) device->data, file_id, size);
     if (result < 0)
@@ -212,11 +217,11 @@ void guac_rdpdr_fs_process_set_disposition_info(guac_rdpdr_device* device,
         output_stream = guac_rdpdr_new_io_completion(device,
                 completion_id, STATUS_SUCCESS, 4);
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i]", file_id);
+
     Stream_Write_UINT32(output_stream, length);
 
     svc_plugin_send((rdpSvcPlugin*) device->rdpdr, output_stream);
-    GUAC_RDP_DEBUG(2, "Sent STATUS_SUCCESS for completion_id=%i",
-            completion_id);
 
 }
 
@@ -230,6 +235,8 @@ void guac_rdpdr_fs_process_set_end_of_file_info(guac_rdpdr_device* device,
     /* Read new size */
     Stream_Read_UINT64(input_stream, size); /* AllocationSize */
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i] size=%" PRIu64, file_id, (uint64_t) size);
+
     /* Truncate file */
     result = guac_rdp_fs_truncate((guac_rdp_fs*) device->data, file_id, size);
     if (result < 0)
@@ -253,9 +260,9 @@ void guac_rdpdr_fs_process_set_basic_info(guac_rdpdr_device* device,
     /* Currently do nothing, just respond */
     Stream_Write_UINT32(output_stream, length);
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i] IGNORED", file_id);
+
     svc_plugin_send((rdpSvcPlugin*) device->rdpdr, output_stream);
-    GUAC_RDP_DEBUG(2, "Sent STATUS_SUCCESS for completion_id=%i",
-            completion_id);
 
 }
 

src/protocols/rdp/guac_rdpdr/rdpdr_fs_messages_vol_info.c

@@ -59,6 +59,8 @@ void guac_rdpdr_fs_process_query_volume_info(guac_rdpdr_device* device,
     wStream* output_stream = guac_rdpdr_new_io_completion(device,
             completion_id, STATUS_SUCCESS, 21 + GUAC_FILESYSTEM_LABEL_LENGTH);
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i]", file_id);
+
     Stream_Write_UINT32(output_stream, 17 + GUAC_FILESYSTEM_LABEL_LENGTH);
     Stream_Write_UINT64(output_stream, 0); /* VolumeCreationTime */
     Stream_Write_UINT32(output_stream, 0); /* VolumeSerialNumber */
@@ -73,16 +75,18 @@ void guac_rdpdr_fs_process_query_volume_info(guac_rdpdr_device* device,
 
 void guac_rdpdr_fs_process_query_size_info(guac_rdpdr_device* device, wStream* input_stream,
         int file_id, int completion_id) {
+
     /* STUB */
-    guac_client_log_error(device->rdpdr->client,
+    GUAC_RDP_DEBUG(2, "[file_id=%i] STUB", file_id);
-            "Unimplemented stub: guac_rdpdr_fs_query_size_info");
+
 }
 
 void guac_rdpdr_fs_process_query_device_info(guac_rdpdr_device* device, wStream* input_stream,
         int file_id, int completion_id) {
+
     /* STUB */
-    guac_client_log_error(device->rdpdr->client,
+    GUAC_RDP_DEBUG(2, "[file_id=%i] STUB", file_id);
-            "Unimplemented stub: guac_rdpdr_fs_query_devive_info");
+
 }
 
 void guac_rdpdr_fs_process_query_attribute_info(guac_rdpdr_device* device, wStream* input_stream,
@@ -91,6 +95,8 @@ void guac_rdpdr_fs_process_query_attribute_info(guac_rdpdr_device* device, wStre
     wStream* output_stream = guac_rdpdr_new_io_completion(device,
             completion_id, STATUS_SUCCESS, 16 + GUAC_FILESYSTEM_NAME_LENGTH);
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i]", file_id);
+
     Stream_Write_UINT32(output_stream, 12 + GUAC_FILESYSTEM_NAME_LENGTH);
     Stream_Write_UINT32(output_stream,
               FILE_UNICODE_ON_DISK
@@ -114,13 +120,14 @@ void guac_rdpdr_fs_process_query_full_size_info(guac_rdpdr_device* device, wStre
     wStream* output_stream = guac_rdpdr_new_io_completion(device,
             completion_id, STATUS_SUCCESS, 16 + GUAC_FILESYSTEM_NAME_LENGTH);
 
+    GUAC_RDP_DEBUG(2, "[file_id=%i]", file_id);
+
     Stream_Write_UINT64(output_stream, info.blocks_total);     /* TotalAllocationUnits */
     Stream_Write_UINT64(output_stream, info.blocks_available); /* CallerAvailableAllocationUnits */
     Stream_Write_UINT64(output_stream, info.blocks_available); /* ActualAvailableAllocationUnits */
     Stream_Write_UINT64(output_stream, 1);                     /* SectorsPerAllocationUnit */
     Stream_Write_UINT64(output_stream, info.block_size);       /* BytesPerSector */
 
-    GUAC_RDP_DEBUG(2, "total=%i, avail=%i, size=%i", info.blocks_total, info.blocks_available, info.block_size);
     svc_plugin_send((rdpSvcPlugin*) device->rdpdr, output_stream);
 
 }