From 87d8d123b81093ec8ce635e3c5009038e5a102f3 Mon Sep 17 00:00:00 2001 From: Henrik Andersson Date: Thu, 26 Jan 2017 14:19:40 +0100 Subject: [PATCH] Rework the logging system This commit will add a logging system to solve the problem that one actually need to recompile rdesktop from source to enable different debug logging. - Same logging api for all kind of logging and messages to end user. - Adding -v for verbose output when running rdesktop. - All messages are logged into a subject and with a type, eg: logger(Keyboard, Notice, "Autos-electing %s based on locale.", locale); - Debug logging is enabled trough a environment variable RDEKSTOP_DEBUG, which specifies subjects of interest, comma separated. There is a special subject named All which includes all subject for debug loggin. There is also a simple logic opeartor '!' = NOT which can be used in combination like: RDESKTOP_DEBUG=All,!Graphics,!Sound Which would give debug log output for All subject except Graphics and Sound. --- README | 3 +- asn.c | 4 +- bitmap.c | 8 +- cache.c | 38 +++--- channels.c | 10 +- cliprdr.c | 22 ++-- configure.ac | 89 ------------- cssp.c | 73 ++++------- ctrl.c | 21 +-- disk.c | 103 ++++++++------- doc/rdesktop.1 | 3 + ewmhints.c | 17 +-- iso.c | 37 ++++-- licence.c | 34 ++--- lspci.c | 15 +-- mcs.c | 17 ++- orders.c | 165 ++++++++++++------------ parallel.c | 16 +-- printer.c | 4 +- printercache.c | 22 ++-- proto.h | 9 -- pstcache.c | 15 ++- rdesktop.c | 160 ++++++++++------------- rdesktop.h | 43 +------ rdp.c | 121 ++++++++++------- rdp5.c | 11 +- rdpdr.c | 86 +++++++------ rdpsnd.c | 73 ++++++----- rdpsnd_alsa.c | 64 ++++++--- rdpsnd_dsp.c | 21 +-- rdpsnd_libao.c | 8 +- rdpsnd_oss.c | 35 +++-- rdpsnd_sgi.c | 74 +++++------ rdpsnd_sun.c | 14 +- scard.c | 342 +++++++++++++++++++++++++++---------------------- seamless.c | 30 ++--- secure.c | 94 +++++++------- serial.c | 172 +++++++++++++------------ ssl.c | 14 +- tcp.c | 46 ++++--- utils.c | 162 ++++++++++++++++++++++- utils.h | 54 ++++++++ xclip.c | 134 +++++++++++-------- xkeymap.c | 93 ++++++++------ xwin.c | 147 ++++++++++++--------- 45 files changed, 1485 insertions(+), 1238 deletions(-) create mode 100644 utils.h diff --git a/README b/README index ddedf44..26b0627 100644 --- a/README +++ b/README @@ -44,6 +44,5 @@ The smart-card support module uses PCSC-lite. You should use PCSC-lite 1.2.9 or later. To enable smart-card support in the rdesktop just run "./configure" with the -"--enable-smartcard" option. Also you can enable smart-card debug with -additional "--with-debug-smartcard" option. +"--enable-smartcard" option. diff --git a/asn.c b/asn.c index 5f039ad..09e67e5 100644 --- a/asn.c +++ b/asn.c @@ -1,7 +1,7 @@ /* -*- c-basic-offset: 8 -*- rdesktop: A Remote Desktop Protocol client. ASN.1 utility functions - Copyright 2012 Henrik Andersson for Cendio AB + Copyright 2012-2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -37,7 +37,7 @@ ber_parse_header(STREAM s, int tagval, int *length) if (tag != tagval) { - error("expected tag %d, got %d\n", tagval, tag); + logger(Core, Error, "ber_parse_header(), expected tag %d, got %d", tagval, tag); return False; } diff --git a/bitmap.c b/bitmap.c index 9acb779..ed10f9e 100644 --- a/bitmap.c +++ b/bitmap.c @@ -252,7 +252,7 @@ bitmap_decompress1(uint8 * output, int width, int height, uint8 * input, int siz REPEAT(line[x] = 0) break; default: - unimpl("bitmap opcode 0x%x\n", opcode); + logger(Core, Warning, "bitmap_decompress(), unhandled bitmap opcode 0x%x", opcode); return False; } } @@ -451,7 +451,7 @@ bitmap_decompress2(uint8 * output, int width, int height, uint8 * input, int siz REPEAT(line[x] = 0) break; default: - unimpl("bitmap opcode 0x%x\n", opcode); + logger(Core, Warning, "bitmap_decompress2(), unhandled bitmap opcode 0x%x", opcode); return False; } } @@ -737,7 +737,7 @@ bitmap_decompress3(uint8 * output, int width, int height, uint8 * input, int siz ) break; default: - unimpl("bitmap opcode 0x%x\n", opcode); + logger(Core, Warning, "bitmap_decompress3(), unhandled bitmap opcode 0x%x", opcode); return False; } } @@ -900,7 +900,7 @@ bitmap_decompress(uint8 * output, int width, int height, uint8 * input, int size rv = bitmap_decompress4(output, width, height, input, size); break; default: - unimpl("Bpp %d\n", Bpp); + logger(Core, Debug, "bitmap_decompress(), unhandled BPP %d", Bpp); break; } return rv; diff --git a/cache.c b/cache.c index d53432f..2a5066b 100644 --- a/cache.c +++ b/cache.c @@ -93,8 +93,9 @@ cache_rebuild_bmpcache_linked_list(uint8 id, sint16 * idx, int count) if (c != g_bmpcache_count[id]) { - error("Oops. %d in bitmap cache linked list, %d in ui cache...\n", c, - g_bmpcache_count[id]); + logger(Core, Error, + "cache_rebuild_bmpcache_linked_list(), %d in bitmap cache linked list, %d in ui cache...", + c, g_bmpcache_count[id]); exit(EX_SOFTWARE); } } @@ -111,7 +112,7 @@ cache_bump_bitmap(uint8 id, uint16 idx, int bump) if (g_bmpcache_mru[id] == idx) return; - DEBUG_RDP5(("bump bitmap: id=%d, idx=%d, bump=%d\n", id, idx, bump)); + logger(Core, Debug, "cache_bump_bitmap(), id=%d, idx=%d, bump=%d", id, idx, bump); n_idx = g_bmpcache[id][idx].next; p_idx = g_bmpcache[id][idx].previous; @@ -177,8 +178,9 @@ cache_evict_bitmap(uint8 id) idx = g_bmpcache_lru[id]; n_idx = g_bmpcache[id][idx].next; - DEBUG_RDP5(("evict bitmap: id=%d idx=%d n_idx=%d bmp=%p\n", id, idx, n_idx, - g_bmpcache[id][idx].bitmap)); + + logger(Core, Debug, "cache_evict_bitmap(), id=%d idx=%d n_idx=%d bmp=%p", id, idx, n_idx, + g_bmpcache[id][idx].bitmap); ui_destroy_bitmap(g_bmpcache[id][idx].bitmap); --g_bmpcache_count[id]; @@ -209,7 +211,8 @@ cache_get_bitmap(uint8 id, uint16 idx) return g_volatile_bc[id]; } - error("get bitmap %d:%d\n", id, idx); + logger(Core, Debug, "cache_get_bitmap(), id=%d, idx=%d", id, idx); + return NULL; } @@ -245,7 +248,7 @@ cache_put_bitmap(uint8 id, uint16 idx, RD_HBITMAP bitmap) } else { - error("put bitmap %d:%d\n", id, idx); + logger(Core, Error, "cache_put_bitmap(), failed, id=%d, idx=%d\n", id, idx); } } @@ -259,14 +262,15 @@ cache_save_state(void) for (id = 0; id < NUM_ELEMENTS(g_bmpcache); id++) if (IS_PERSISTENT(id)) { - DEBUG_RDP5(("Saving cache state for bitmap cache %d...", id)); + logger(Core, Debug, + "cache_save_state(), saving cache state for bitmap cache %d", id); idx = g_bmpcache_lru[id]; while (idx >= 0) { pstcache_touch_bitmap(id, idx, ++t); idx = g_bmpcache[id][idx].next; } - DEBUG_RDP5((" %d stamps written.\n", t)); + logger(Core, Debug, "cache_save_state(), %d stamps written", t); } } @@ -287,7 +291,7 @@ cache_get_font(uint8 font, uint16 character) return glyph; } - error("get font %d:%d\n", font, character); + logger(Core, Debug, "cache_get_font(), font=%d, char=%d", font, character); return NULL; } @@ -312,7 +316,7 @@ cache_put_font(uint8 font, uint16 character, uint16 offset, } else { - error("put font %d:%d\n", font, character); + logger(Core, Error, "cache_put_font(), failed, font=%d, char=%d", font, character); } } @@ -362,7 +366,7 @@ cache_get_desktop(uint32 offset, int cx, int cy, int bytes_per_pixel) return &g_deskcache[offset]; } - error("get desktop %d:%d\n", offset, length); + logger(Core, Debug, "cache_get_desktop(), offset=%d, length=%d", offset, length); return NULL; } @@ -387,7 +391,7 @@ cache_put_desktop(uint32 offset, int cx, int cy, int scanline, int bytes_per_pix } else { - error("put desktop %d:%d\n", offset, length); + logger(Core, Error, "cache_put_desktop(), offset=%d, length=%d", offset, length); } } @@ -408,7 +412,7 @@ cache_get_cursor(uint16 cache_idx) return cursor; } - error("get cursor %d\n", cache_idx); + logger(Core, Debug, "cache_get_cursor(), idx=%d", cache_idx); return NULL; } @@ -428,7 +432,7 @@ cache_put_cursor(uint16 cache_idx, RD_HCURSOR cursor) } else { - error("put cursor %d\n", cache_idx); + logger(Core, Error, "cache_put_cursor(), failed, idx=%d", cache_idx); } } @@ -445,7 +449,7 @@ cache_get_brush_data(uint8 colour_code, uint8 idx) { return &g_brushcache[colour_code][idx]; } - error("get brush %d %d\n", colour_code, idx); + logger(Core, Debug, "cache_get_brush_data(), colour=%d, idx=%d", colour_code, idx); return NULL; } @@ -468,6 +472,6 @@ cache_put_brush_data(uint8 colour_code, uint8 idx, BRUSHDATA * brush_data) } else { - error("put brush %d %d\n", colour_code, idx); + logger(Core, Error, "cache_put_brush_data(), colour=%d, idx=%d", colour_code, idx); } } diff --git a/channels.c b/channels.c index 42328f2..3c7e8ea 100644 --- a/channels.c +++ b/channels.c @@ -52,7 +52,8 @@ channel_register(char *name, uint32 flags, void (*callback) (STREAM)) if (g_num_channels >= MAX_CHANNELS) { - error("Channel table full, increase MAX_CHANNELS\n"); + logger(Core, Error, + "channel_register(), channel table full, increase MAX_CHANNELS"); return NULL; } @@ -90,7 +91,7 @@ channel_send(STREAM s, VCHANNEL * channel) s_pop_layer(s, channel_hdr); length = s->end - s->p - 8; - DEBUG_CHANNEL(("channel_send, length = %d\n", length)); + logger(Protocol, Debug, "channel_send(), length = %d", length); thislength = MIN(length, CHANNEL_CHUNK_LENGTH); /* Note: In the original clipboard implementation, this number was @@ -105,7 +106,7 @@ channel_send(STREAM s, VCHANNEL * channel) out_uint32_le(s, length); out_uint32_le(s, flags); data = s->end = s->p + thislength; - DEBUG_CHANNEL(("Sending %d bytes with FLAG_FIRST\n", thislength)); + logger(Protocol, Debug, "channel_send(), sending %d bytes with FLAG_FIRST set", thislength); sec_send_to_channel(s, g_encryption ? SEC_ENCRYPT : 0, channel->mcs_id); /* subsequent segments copied (otherwise would have to generate headers backwards) */ @@ -117,7 +118,8 @@ channel_send(STREAM s, VCHANNEL * channel) if (channel->flags & CHANNEL_OPTION_SHOW_PROTOCOL) flags |= CHANNEL_FLAG_SHOW_PROTOCOL; - DEBUG_CHANNEL(("Sending %d bytes with flags %d\n", thislength, flags)); + logger(Protocol, Debug, "channel_send(), sending %d bytes with flags 0x%x", + thislength, flags); s = sec_init(g_encryption ? SEC_ENCRYPT : 0, thislength + 8); out_uint32_le(s, length); diff --git a/cliprdr.c b/cliprdr.c index ee0027d..3f68213 100644 --- a/cliprdr.c +++ b/cliprdr.c @@ -3,6 +3,7 @@ Protocol services - Clipboard functions Copyright 2003 Erik Forsberg for Cendio AB Copyright (C) Matthew Chapman 2003-2008 + Copyright 2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -40,7 +41,8 @@ cliprdr_send_packet(uint16 type, uint16 status, uint8 * data, uint32 length) { STREAM s; - DEBUG_CLIPBOARD(("CLIPRDR send: type=%d, status=%d, length=%d\n", type, status, length)); + logger(Clipboard, Debug, "cliprdr_send_packet(), type=%d, status=%d, length=%d", type, + status, length); s = channel_init(cliprdr_channel, length + 12); out_uint16_le(s, type); @@ -62,7 +64,8 @@ cliprdr_send_simple_native_format_announce(uint32 format) { uint8 buffer[36]; - DEBUG_CLIPBOARD(("cliprdr_send_simple_native_format_announce\n")); + logger(Clipboard, Debug, "cliprdr_send_simple_native_format_announce() format 0x%x", + format); buf_out_uint32(buffer, format); memset(buffer + 4, 0, sizeof(buffer) - 4); /* description */ @@ -76,7 +79,7 @@ cliprdr_send_simple_native_format_announce(uint32 format) void cliprdr_send_native_format_announce(uint8 * formats_data, uint32 formats_data_length) { - DEBUG_CLIPBOARD(("cliprdr_send_native_format_announce\n")); + logger(Clipboard, Debug, "cliprdr_send_native_format_announce()"); cliprdr_send_packet(CLIPRDR_FORMAT_ANNOUNCE, CLIPRDR_REQUEST, formats_data, formats_data_length); @@ -97,7 +100,7 @@ cliprdr_send_data_request(uint32 format) { uint8 buffer[4]; - DEBUG_CLIPBOARD(("cliprdr_send_data_request\n")); + logger(Clipboard, Debug, "cliprdr_send_data_request(), format 0x%x", format); buf_out_uint32(buffer, format); cliprdr_send_packet(CLIPRDR_DATA_REQUEST, CLIPRDR_REQUEST, buffer, sizeof(buffer)); } @@ -105,7 +108,7 @@ cliprdr_send_data_request(uint32 format) void cliprdr_send_data(uint8 * data, uint32 length) { - DEBUG_CLIPBOARD(("cliprdr_send_data\n")); + logger(Clipboard, Debug, "cliprdr_send_data(), length %d bytes", length); cliprdr_send_packet(CLIPRDR_DATA_RESPONSE, CLIPRDR_RESPONSE, data, length); } @@ -121,7 +124,8 @@ cliprdr_process(STREAM s) in_uint32_le(s, length); data = s->p; - DEBUG_CLIPBOARD(("CLIPRDR recv: type=%d, status=%d, length=%d\n", type, status, length)); + logger(Clipboard, Debug, "cliprdr_process(), type=%d, status=%d, length=%d", type, status, + length); if (status == CLIPRDR_ERROR) { @@ -137,7 +141,8 @@ cliprdr_process(STREAM s) ui_clip_request_failed(); break; default: - DEBUG_CLIPBOARD(("CLIPRDR error (type=%d)\n", type)); + logger(Clipboard, Warning, + "cliprdr_process(), unhandled error (type=%d)", type); } return; @@ -164,7 +169,8 @@ cliprdr_process(STREAM s) case 7: /* TODO: W2K3 SP1 sends this on connect with a value of 1 */ break; default: - unimpl("CLIPRDR packet type %d\n", type); + logger(Clipboard, Warning, "cliprdr_process(), unhandled packet type %d", + type); } } diff --git a/configure.ac b/configure.ac index 1f3962d..e045c40 100644 --- a/configure.ac +++ b/configure.ac @@ -860,95 +860,6 @@ AC_ARG_WITH(ipv6, fi ]) - -# -# debugging -# -AC_ARG_WITH(debug, - [ --with-debug enable protocol debugging output], - [ - if test $withval != "no"; - then - AC_DEFINE(WITH_DEBUG,1) - fi - ]) - -AC_ARG_WITH(debug-kbd, - [ --with-debug-kbd enable debugging of keyboard handling], - [ - if test $withval != "no"; - then - AC_DEFINE(WITH_DEBUG_KBD,1) - fi - ]) - -AC_ARG_WITH(debug-rdp5, - [ --with-debug-rdp5 enable debugging of RDP5 code], - [ - if test $withval != "no"; - then - AC_DEFINE(WITH_DEBUG_RDP5,1) - fi - ]) - -AC_ARG_WITH(debug-clipboard, - [ --with-debug-clipboard enable debugging of clipboard code], - [ - if test $withval != "no"; - then - AC_DEFINE(WITH_DEBUG_CLIPBOARD,1) - fi - ]) - -AC_ARG_WITH(debug-sound, - [ --with-debug-sound enable debugging of sound code], - [ - if test $withval != "no"; - then - AC_DEFINE(WITH_DEBUG_SOUND,1) - fi - ]) - -AC_ARG_WITH(debug-channel, - [ --with-debug-channel enable debugging of virtual channel code], - [ - if test $withval != "no"; - then - AC_DEFINE(WITH_DEBUG_CHANNEL,1) - fi - ]) - -AC_ARG_WITH(debug-seamless, - [ --with-debug-seamless enable debugging of SeamlessRDP code], - [ - if test $withval != "no"; - then - AC_DEFINE(WITH_DEBUG_SEAMLESS,1) - fi - ]) - -AC_ARG_WITH(debug-smartcard, - [ --with-debug-smartcard enable debugging of smart-card code], - [ - if test $withval != "no"; - then - if test x"$WITH_SCARD" = "x1"; then - AC_DEFINE(WITH_DEBUG_SCARD,1) - fi - fi - ]) - -AC_ARG_WITH(debug-credssp, - [ --with-debug-credssp enable debugging of CredSSP code], - [ - if test $withval != "no"; - then - if test x"$WITH_CREDSSP" = "x1"; then - AC_DEFINE(WITH_DEBUG_CREDSSP,1) - fi - fi - ]) - # # target-specific stuff # diff --git a/cssp.c b/cssp.c index 8f5bdd1..9f4c082 100644 --- a/cssp.c +++ b/cssp.c @@ -1,7 +1,7 @@ /* -*- c-basic-offset: 8 -*- rdesktop: A Remote Desktop Protocol client. CredSSP layer and kerberos support. - Copyright 2012-2013 Henrik Andersson for Cendio AB + Copyright 2012-2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -84,10 +84,10 @@ cssp_gss_report_error(OM_uint32 code, char *str, OM_uint32 major_status, OM_uint OM_uint32 msgctx = 0, ms; gss_buffer_desc status_string; - error("GSS error [%d:%d:%d]: %s\n", (major_status & 0xff000000) >> 24, // Calling error - (major_status & 0xff0000) >> 16, // Routine error - major_status & 0xffff, // Supplementary info bits - str); + logger(Core, Debug, "GSS error [%d:%d:%d]: %s", (major_status & 0xff000000) >> 24, // Calling error + (major_status & 0xff0000) >> 16, // Routine error + major_status & 0xffff, // Supplementary info bits + str); do { @@ -96,7 +96,7 @@ cssp_gss_report_error(OM_uint32 code, char *str, OM_uint32 major_status, OM_uint if (ms != GSS_S_COMPLETE) continue; - error(" - %s\n", status_string.value); + logger(Core, Debug, " - %s", status_string.value); } while (ms == GSS_S_COMPLETE && msgctx); @@ -195,7 +195,8 @@ cssp_gss_wrap(gss_ctx_id_t * ctx, STREAM in, STREAM out) if (!conf_state) { - error("GSS Confidentiality failed, no encryption of message performed."); + logger(Core, Error, + "cssp_gss_wrap(), GSS Confidentiality failed, no encryption of message performed."); return False; } @@ -241,15 +242,6 @@ cssp_gss_unwrap(gss_ctx_id_t * ctx, STREAM in, STREAM out) return True; } -#ifdef WITH_DEBUG_CREDSSP -void -streamsave(STREAM s, char *fn) -{ - FILE *f = fopen(fn, "wb"); - fwrite(s->data, s_length(s), 1, f); - fclose(f); -} -#endif static STREAM cssp_encode_tspasswordcreds(char *username, char *password, char *domain) @@ -535,12 +527,6 @@ cssp_encode_tscredentials(char *username, char *password, char *domain) // Construct ASN.1 message out = ber_wrap_hdr_data(BER_TAG_SEQUENCE | BER_TAG_CONSTRUCTED, &message); -#if WITH_DEBUG_CREDSSP - streamsave(out, "tscredentials.raw"); - printf("Out TSCredentials %ld bytes\n", s_length(out)); - hexdump(out->data, s_length(out)); -#endif - // cleanup xfree(message.data); xfree(tmp.data); @@ -626,12 +612,6 @@ cssp_send_tsrequest(STREAM token, STREAM auth, STREAM pubkey) s_mark_end(s); s_free(h1); -#if WITH_DEBUG_CREDSSP - streamsave(s, "tsrequest_out.raw"); - printf("Out TSRequest %ld bytes\n", s_length(s)); - hexdump(s->data, s_length(s)); -#endif - tcp_send(s); // cleanup @@ -657,7 +637,9 @@ cssp_read_tsrequest(STREAM token, STREAM pubkey) // verify ASN.1 header if (s->p[0] != (BER_TAG_SEQUENCE | BER_TAG_CONSTRUCTED)) { - error("Expected BER_TAG_SEQUENCE|BER_TAG_CONSTRUCTED, got %x", s->p[0]); + logger(Protocol, Error, + "cssp_read_tsrequest(), expected BER_TAG_SEQUENCE|BER_TAG_CONSTRUCTED, got %x", + s->p[0]); return False; } @@ -674,12 +656,6 @@ cssp_read_tsrequest(STREAM token, STREAM pubkey) // receive the remainings of message s = tcp_recv(s, length); -#if WITH_DEBUG_CREDSSP - streamsave(s, "tsrequest_in.raw"); - printf("In TSRequest token %ld bytes\n", s_length(s)); - hexdump(s->data, s_length(s)); -#endif - // parse the response and into nego token if (!ber_in_header(s, &tagval, &length) || tagval != (BER_TAG_SEQUENCE | BER_TAG_CONSTRUCTED)) @@ -754,30 +730,27 @@ cssp_connect(char *server, char *user, char *domain, char *password, STREAM s) // Verify that system gss support spnego if (!cssp_gss_mech_available(desired_mech)) { - warning("CredSSP: System doesn't have support for desired authentication mechanism.\n"); + logger(Core, Debug, + "cssp_connect(), system doesn't have support for desired authentication mechanism"); return False; } // Get service name if (!cssp_gss_get_service_name(server, &target_name)) { - warning("CredSSP: Failed to get target service name.\n"); + logger(Core, Debug, "cssp_connect(), failed to get target service name"); return False; } // Establish tls connection to server if (!tcp_tls_connect()) { - warning("CredSSP: Failed to establish TLS connection.\n"); + logger(Core, Debug, "cssp_connect(), failed to establish TLS connection"); return False; } tcp_tls_get_server_pubkey(&pubkey); -#ifdef WITH_DEBUG_CREDSSP - streamsave(&pubkey, "PubKey.raw"); -#endif - // Enter the spnego loop OM_uint32 actual_services; gss_OID actual_mech; @@ -809,21 +782,21 @@ cssp_connect(char *server, char *user, char *domain, char *password, STREAM s) if (GSS_ERROR(major_status)) { if (i == 0) - error("CredSSP: Initialize failed, do you have correct kerberos tgt initialized ?\n"); + logger(Core, Notice, + "Failed to intialize NLA, do you have correct kerberos tgt initialized ?"); else - error("CredSSP: Negotiation failed.\n"); + logger(Core, Error, "cssp_connect(), negotiation failed"); -#ifdef WITH_DEBUG_CREDSSP - cssp_gss_report_error(GSS_C_GSS_CODE, "CredSSP: SPNEGO negotiation failed.", + cssp_gss_report_error(GSS_C_GSS_CODE, "cssp_connect(), negotiation failed.", major_status, minor_status); -#endif goto bail_out; } // validate required services if (!(actual_services & GSS_C_CONF_FLAG)) { - error("CredSSP: Confidiality service required but is not available.\n"); + logger(Core, Error, + "cssp_connect(), confidiality service required but is not available"); goto bail_out; } @@ -885,8 +858,8 @@ cssp_connect(char *server, char *user, char *domain, char *password, STREAM s) // validate public key if (memcmp(pubkey.data, pubkey_cmp.data, s_length(&pubkey)) != 0) { - error("CredSSP: Cannot guarantee integrity of server connection, MITM ? " - "(public key data mismatch)\n"); + logger(Core, Error, + "cssp_connect(), public key mismatch, cannot guarantee integrity of server connection"); goto bail_out; } diff --git a/ctrl.c b/ctrl.c index 92a39b9..744aee5 100644 --- a/ctrl.c +++ b/ctrl.c @@ -1,7 +1,7 @@ /* -*- c-basic-offset: 8 -*- rdesktop: A Remote Desktop Protocol client. Master/Slave remote controlling - Copyright 2013 Henrik Andersson for Cendio AB + Copyright 2013-2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -25,6 +25,7 @@ #include #include #include +#include #include #include @@ -186,7 +187,8 @@ _ctrl_verify_unix_socket() if ((s = socket(AF_UNIX, SOCK_STREAM, 0)) < 0) { - perror("Error creating ctrl client socket: socket()"); + logger(Core, Error, "_ctrl_verify_unix_socket(), socket() failed: %s", + strerror(errno)); exit(1); } @@ -274,7 +276,7 @@ ctrl_init(const char *user, const char *domain, const char *host) path[sizeof(path) - 1] = '\0'; if (utils_mkdir_p(path, 0700) == -1) { - perror(path); + logger(Core, Error, "ctrl_init(), utils_mkdir_p() failed: %s", strerror(errno)); return -1; } @@ -296,7 +298,7 @@ ctrl_init(const char *user, const char *domain, const char *host) /* setup ctrl socket and start listening for connections */ if ((ctrlsock = socket(AF_UNIX, SOCK_STREAM, 0)) < 0) { - perror("Error creating ctrl socket:"); + logger(Core, Error, "ctrl_init(), socket() failed: %s", strerror(errno)); exit(1); } @@ -306,13 +308,13 @@ ctrl_init(const char *user, const char *domain, const char *host) strncpy(saun.sun_path, ctrlsock_name, sizeof(saun.sun_path)); if (bind(ctrlsock, (struct sockaddr *) &saun, sizeof(struct sockaddr_un)) < 0) { - perror("Error binding ctrl socket:"); + logger(Core, Error, "ctrl_init(), bind() failed: %s", strerror(errno)); exit(1); } if (listen(ctrlsock, 5) < 0) { - perror("Error listening on socket:"); + logger(Core, Error, "ctrl_init(), listen() failed: %s", strerror(errno)); exit(1); } @@ -381,7 +383,8 @@ ctrl_check_fds(fd_set * rfds, fd_set * wfds) ns = accept(ctrlsock, (struct sockaddr *) &fsaun, &fromlen); if (ns < 0) { - perror("server: accept()"); + logger(Core, Error, "ctrl_check_fds(), accept() failed: %s", + strerror(errno)); exit(1); } @@ -459,7 +462,7 @@ ctrl_send_command(const char *cmd, const char *arg) if ((s = socket(AF_UNIX, SOCK_STREAM, 0)) < 0) { - perror("Error creating ctrl client socket: socket()"); + logger(Core, Error, "ctrl_send_command(), socket() failed: %s", strerror(errno)); exit(1); } @@ -470,7 +473,7 @@ ctrl_send_command(const char *cmd, const char *arg) if (connect(s, (struct sockaddr *) &saun, len) < 0) { - perror("Error connecting to ctrl socket: connect()"); + logger(Core, Error, "ctrl_send_command(), connect() failed: %s", strerror(errno)); exit(1); } diff --git a/disk.c b/disk.c index 223d64b..76ef4c9 100644 --- a/disk.c +++ b/disk.c @@ -3,6 +3,7 @@ Disk Redirection Copyright (C) Jeroen Meijer 2003-2008 Copyright 2003-2011 Peter Astrand for Cendio AB + Copyright 2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -219,35 +220,35 @@ ftruncate_growable(int fd, off_t length) /* Get current position */ if ((pos = lseek(fd, 0, SEEK_CUR)) == -1) { - perror("lseek"); + logger(Core, Error, "ftruncate_growable(), lseek() failed: %s", strerror(errno)); return -1; } /* Seek to new size */ if (lseek(fd, length, SEEK_SET) == -1) { - perror("lseek"); + logger(Core, Error, "ftruncate_growable(), lseek() failed: %s", strerror(errno)); return -1; } /* Write a zero */ if (write(fd, &zero, 1) == -1) { - perror("write"); + logger(Core, Error, "ftruncate_growable(), write() failed: %s", strerror(errno)); return -1; } /* Truncate. This shouldn't fail. */ if (ftruncate(fd, length) == -1) { - perror("ftruncate"); + logger(Core, Error, "ftruncate_growable(), ftruncate() failed: %s", strerror(errno)); return -1; } /* Restore position */ if (lseek(fd, pos, SEEK_SET) == -1) { - perror("lseek"); + logger(Core, Error, "ftruncate_growable(), lseek() failed: %s", strerror(errno)); return -1; } @@ -324,8 +325,8 @@ disk_enum_devices(uint32 * id, char *optarg) strncpy(g_rdpdr_device[*id].name, optarg, sizeof(g_rdpdr_device[*id].name) - 1); if (strlen(optarg) > (sizeof(g_rdpdr_device[*id].name) - 1)) - fprintf(stderr, "share name %s truncated to %s\n", optarg, - g_rdpdr_device[*id].name); + logger(Core, Warning, "disk_enum_devices(), share name %s truncated to %s", + optarg, g_rdpdr_device[*id].name); g_rdpdr_device[*id].local_path = (char *) xmalloc(strlen(pos2) + 1); strcpy(g_rdpdr_device[*id].local_path, pos2); @@ -437,8 +438,8 @@ disk_create(uint32 device_id, uint32 accessmask, uint32 sharemode, uint32 create return RD_STATUS_NO_SUCH_FILE; default: - - perror("opendir"); + logger(Core, Error, "disk_create(), opendir() failed: %s", + strerror(errno)); return RD_STATUS_NO_SUCH_FILE; } } @@ -481,21 +482,23 @@ disk_create(uint32 device_id, uint32 accessmask, uint32 sharemode, uint32 create return RD_STATUS_OBJECT_NAME_COLLISION; default: - - perror("open"); + logger(Core, Error, "disk_create(), open() failed: %s", + strerror(errno)); return RD_STATUS_NO_SUCH_FILE; } } /* all read and writes of files should be non blocking */ if (fcntl(handle, F_SETFL, O_NONBLOCK) == -1) - perror("fcntl"); + logger(Core, Error, "disk_create(), fcntl() failed: %s", strerror(errno)); + } if (handle >= MAX_OPEN_FILES) { - error("Maximum number of open files (%s) reached. Increase MAX_OPEN_FILES!\n", - handle); + logger(Core, Error, + "disk_create(), maximum number of open files (%s) reached, increase MAX_OPEN_FILES!", + handle); exit(EX_SOFTWARE); } @@ -533,14 +536,15 @@ disk_close(RD_NTHANDLE handle) { if (closedir(pfinfo->pdir) < 0) { - perror("closedir"); + logger(Core, Error, "disk_close(), closedir() failed: %s", strerror(errno)); return RD_STATUS_INVALID_HANDLE; } if (pfinfo->delete_on_close) if (rmdir(pfinfo->path) < 0) { - perror(pfinfo->path); + logger(Core, Error, "disk_close(), rmdir() failed: %s", + strerror(errno)); return RD_STATUS_ACCESS_DENIED; } pfinfo->delete_on_close = False; @@ -549,13 +553,14 @@ disk_close(RD_NTHANDLE handle) { if (close(handle) < 0) { - perror("close"); + logger(Core, Error, "disk_close(), close() failed: %s", strerror(errno)); return RD_STATUS_INVALID_HANDLE; } if (pfinfo->delete_on_close) if (unlink(pfinfo->path) < 0) { - perror(pfinfo->path); + logger(Core, Error, "disk_close(), unlink() failed: %s", + strerror(errno)); return RD_STATUS_ACCESS_DENIED; } @@ -595,7 +600,8 @@ disk_read(RD_NTHANDLE handle, uint8 * data, uint32 length, uint32 offset, uint32 /* return STATUS_FILE_IS_A_DIRECTORY; */ return RD_STATUS_NOT_IMPLEMENTED; default: - perror("read"); + logger(Core, Error, "disk_read(), read failed: %s", + strerror(errno)); return RD_STATUS_INVALID_PARAMETER; } } @@ -616,7 +622,7 @@ disk_write(RD_NTHANDLE handle, uint8 * data, uint32 length, uint32 offset, uint3 if (n < 0) { - perror("write"); + logger(Core, Error, "disk_write(), write() failed: %s", strerror(errno)); *result = 0; switch (errno) { @@ -644,7 +650,7 @@ disk_query_information(RD_NTHANDLE handle, uint32 info_class, STREAM out) /* Get information about file */ if (fstat(handle, &filestat) != 0) { - perror("stat"); + logger(Core, Error, "disk_query_information(), stat() failed: %s", strerror(errno)); out_uint8(out, 0); return RD_STATUS_ACCESS_DENIED; } @@ -709,8 +715,9 @@ disk_query_information(RD_NTHANDLE handle, uint32 info_class, STREAM out) break; default: - - unimpl("IRP Query (File) Information class: 0x%x\n", info_class); + logger(Protocol, Warning, + "disk_query_information(), unhandled query information class 0x%x", + info_class); return RD_STATUS_INVALID_PARAMETER; } return RD_STATUS_SUCCESS; @@ -784,12 +791,9 @@ disk_set_information(RD_NTHANDLE handle, uint32 info_class, STREAM in, STREAM ou if (access_time || write_time || change_time) { -#if WITH_DEBUG_RDP5 - printf("FileBasicInformation access time %s", - ctime(&tvs.actime)); - printf("FileBasicInformation modification time %s", - ctime(&tvs.modtime)); -#endif + logger(Protocol, Debug, + "disk_set_information(), access time='%s', modify time='%s'", + ctime(&tvs.actime), ctime(&tvs.modtime)); if (utime(pfinfo->path, &tvs) && errno != EPERM) return RD_STATUS_ACCESS_DENIED; } @@ -805,9 +809,8 @@ disk_set_information(RD_NTHANDLE handle, uint32 info_class, STREAM in, STREAM ou mode |= S_IWUSR; mode &= 0777; -#if WITH_DEBUG_RDP5 - printf("FileBasicInformation set access mode 0%o", mode); -#endif + + logger(Protocol, Debug, "disk_set_information(), access mode 0%o", mode); if (fchmod(handle, mode)) return RD_STATUS_ACCESS_DENIED; @@ -836,7 +839,8 @@ disk_set_information(RD_NTHANDLE handle, uint32 info_class, STREAM in, STREAM ou if (rename(pfinfo->path, fullpath) != 0) { - perror("rename"); + logger(Core, Error, "disk_set_information(), rename() failed: %s", + strerror(errno)); return RD_STATUS_ACCESS_DENIED; } break; @@ -918,8 +922,9 @@ disk_set_information(RD_NTHANDLE handle, uint32 info_class, STREAM in, STREAM ou break; default: - - unimpl("IRP Set File Information class: 0x%x\n", info_class); + logger(Protocol, Warning, + "disk_set_information(), unhandled information class 0x%x", + info_class); return RD_STATUS_INVALID_PARAMETER; } return RD_STATUS_SUCCESS; @@ -995,7 +1000,7 @@ NotifyInfo(RD_NTHANDLE handle, uint32 info_class, NOTIFY * p) pfinfo = &(g_fileinfo[handle]); if (fstat(handle, &filestat) < 0) { - perror("NotifyInfo"); + logger(Core, Error, "NotifyInfo(), fstat failed: %s", strerror(errno)); return RD_STATUS_ACCESS_DENIED; } p->modify_time = filestat.st_mtime; @@ -1007,7 +1012,7 @@ NotifyInfo(RD_NTHANDLE handle, uint32 info_class, NOTIFY * p) dpr = opendir(pfinfo->path); if (!dpr) { - perror("NotifyInfo"); + logger(Core, Error, "NotifyInfo(), opendir failed: %s", strerror(errno)); return RD_STATUS_ACCESS_DENIED; } @@ -1111,7 +1116,8 @@ disk_query_volume_information(RD_NTHANDLE handle, uint32 info_class, STREAM out) if (STATFS_FN(pfinfo->path, &stat_fs) != 0) { - perror("statfs"); + logger(Core, Error, "disk_query_volume_information(), statfs() failed: %s", + strerror(errno)); return RD_STATUS_ACCESS_DENIED; } @@ -1169,8 +1175,9 @@ disk_query_volume_information(RD_NTHANDLE handle, uint32 info_class, STREAM out) case FileFsMaximumInformation: default: - - unimpl("IRP Query Volume Information class: 0x%x\n", info_class); + logger(Protocol, Warning, + "disk_query_volume_information(), unhandled volume info class 0x%x", + info_class); return RD_STATUS_INVALID_PARAMETER; } return RD_STATUS_SUCCESS; @@ -1230,7 +1237,9 @@ disk_query_directory(RD_NTHANDLE handle, uint32 info_class, char *pattern, STREA default: /* Fatal error. By returning STATUS_NO_SUCH_FILE, the directory list operation will be aborted */ - perror(fullpath); + logger(Core, Error, + "disk_query_directory(), stat() failed: %s", + strerror(errno)); out_uint8(out, 0); return RD_STATUS_NO_SUCH_FILE; } @@ -1251,7 +1260,9 @@ disk_query_directory(RD_NTHANDLE handle, uint32 info_class, char *pattern, STREA break; default: - unimpl("IRP Query Directory sub: 0x%x\n", info_class); + logger(Protocol, Warning, + "disk_query_directory(), unhandled directory info class 0x%x", + info_class); return RD_STATUS_INVALID_PARAMETER; } @@ -1359,8 +1370,9 @@ disk_query_directory(RD_NTHANDLE handle, uint32 info_class, char *pattern, STREA default: - - unimpl("IRP Query Directory sub: 0x%x\n", info_class); + logger(Protocol, Warning, + "disk_query_directory(), unhandled directory info class 0x%x", + info_class); return RD_STATUS_INVALID_PARAMETER; } @@ -1386,7 +1398,8 @@ disk_device_control(RD_NTHANDLE handle, uint32 request, STREAM in, STREAM out) case 25: /* ? */ case 42: /* ? */ default: - unimpl("DISK IOCTL %d\n", request); + logger(Protocol, Warning, "disk_device_control(), unhandled disk ioctl %d", + request); return RD_STATUS_INVALID_PARAMETER; } diff --git a/doc/rdesktop.1 b/doc/rdesktop.1 index 709fbec..86b8c11 100644 --- a/doc/rdesktop.1 +++ b/doc/rdesktop.1 @@ -240,6 +240,9 @@ Use RDP version 4. .TP .BR "-5" Use RDP version 5 (default). +.TP +.BR "-v" +Enable verbose output .PP .SH "CredSSP Smartcard options" diff --git a/ewmhints.c b/ewmhints.c index 5d3c45c..1478997 100644 --- a/ewmhints.c +++ b/ewmhints.c @@ -57,7 +57,7 @@ get_property_value(Window wnd, char *propname, long max_length, property = XInternAtom(g_display, propname, True); if (property == None) { - fprintf(stderr, "Atom %s does not exist\n", propname); + logger(GUI, Error, "get_property_value(), atom '%s' does not exist", propname); return (-1); } @@ -71,26 +71,27 @@ get_property_value(Window wnd, char *propname, long max_length, if (result != Success) { - fprintf(stderr, "XGetWindowProperty failed\n"); + logger(GUI, Error, "get_property_value(), XGetWindowProperty failed"); return (-1); } if (actual_type_return == None || actual_format_return == 0) { if (!nowarn) - fprintf(stderr, "Window is missing property %s\n", propname); + logger(GUI, Error, "get_property_value(), window is missing atom '%s'", + propname); return (-1); } if (bytes_after_return) { - fprintf(stderr, "%s is too big for me\n", propname); + logger(GUI, Error, "get_property_value(), atom '%s' is too big for me", propname); return (-1); } if (actual_format_return != 32) { - fprintf(stderr, "%s has bad format\n", propname); + logger(GUI, Error, "get_property_value(), atom '%s' has bad format", propname); return (-1); } @@ -115,7 +116,7 @@ get_current_desktop(void) if (nitems_return != 1) { - fprintf(stderr, "_NET_CURRENT_DESKTOP has bad length\n"); + logger(GUI, Error, "get_current_desktop(), _NET_CURRENT_DESKTOP has bad length"); return (-1); } @@ -149,7 +150,7 @@ get_current_workarea(uint32 * x, uint32 * y, uint32 * width, uint32 * height) if (nitems_return % 4) { - fprintf(stderr, "_NET_WORKAREA has odd length\n"); + logger(GUI, Error, "get_current_workare(),_NET_WORKAREA has bad length"); return (-1); } @@ -369,7 +370,7 @@ ewmh_get_window_desktop(Window wnd) if (nitems_return != 1) { - fprintf(stderr, "_NET_WM_DESKTOP has bad length\n"); + logger(GUI, Error, "ewmh_get_window_desktop(), _NET_WM_DESKTOP has bad length"); return (-1); } diff --git a/iso.c b/iso.c index 5232da9..4b5c6e0 100644 --- a/iso.c +++ b/iso.c @@ -126,7 +126,7 @@ iso_recv_msg(uint8 * code, uint8 * rdpver) } if (length < 4) { - error("Bad packet header\n"); + logger(Protocol, Error, "iso_recv_msg(), bad packet header, length < 4"); return NULL; } s = tcp_recv(s, length - 4); @@ -192,7 +192,7 @@ iso_recv(uint8 * rdpver) return s; if (code != ISO_PDU_DT) { - error("expected DT, got 0x%x\n", code); + logger(Protocol, Error, "iso_recv(), expected ISO_PDU_DT, got 0x%x", code); return NULL; } return s; @@ -217,8 +217,13 @@ iso_connect(char *server, char *username, char *domain, char *password, else if (g_sc_csp_name || g_sc_reader_name || g_sc_card_name || g_sc_container_name) neg_proto |= PROTOCOL_HYBRID; else - warning("Disables CredSSP due to missing smartcard information for SSO.\n"); + logger(Core, Warning, + "iso_connect(), missing smartcard information for SSO, disabling CredSSP"); #endif + if (neg_proto & PROTOCOL_HYBRID) + logger(Core, Verbose, "Connecting to server using NLA..."); + else + logger(Core, Verbose, "Connecting to server using SSL..."); retry: *selected_protocol = PROTOCOL_RDP; @@ -235,7 +240,7 @@ iso_connect(char *server, char *username, char *domain, char *password, if (code != ISO_PDU_CC) { - error("expected CC, got 0x%x\n", code); + logger(Protocol, Error, "iso_connect(), expected ISO_PDU_CC, got 0x%x", code); tcp_disconnect(); return False; } @@ -288,20 +293,21 @@ iso_connect(char *server, char *username, char *domain, char *password, if (retry_without_neg) { - fprintf(stderr, - "Failed to negotiate protocol, retrying with plain RDP.\n"); + logger(Core, Notice, + "Failed to negotiate protocol, retrying with plain RDP."); g_negotiate_rdp_protocol = False; goto retry; } - fprintf(stderr, "Failed to connect, %s.\n", reason); + logger(Core, Notice, "Failed to connect, %s.\n", reason); return False; } if (type != RDP_NEG_RSP) { tcp_disconnect(); - error("Expected RDP_NEG_RSP, got type = 0x%x\n", type); + logger(Protocol, Error, "iso_connect(), expected RDP_NEG_RSP, got 0x%x", + type); return False; } @@ -311,13 +317,15 @@ iso_connect(char *server, char *username, char *domain, char *password, if (!tcp_tls_connect()) { /* failed to connect using cssp, let retry with plain TLS */ + logger(Core, Verbose, + "Failed to connect using SSL, trying with plain RDP."); tcp_disconnect(); neg_proto = PROTOCOL_RDP; goto retry; } /* do not use encryption when using TLS */ g_encryption = False; - fprintf(stderr, "Connection established using SSL.\n"); + logger(Core, Notice, "Connection established using SSL."); } #ifdef WITH_CREDSSP else if (data == PROTOCOL_HYBRID) @@ -325,25 +333,28 @@ iso_connect(char *server, char *username, char *domain, char *password, if (!cssp_connect(server, username, domain, password, s)) { /* failed to connect using cssp, let retry with plain TLS */ + logger(Core, Verbose, + "Failed to connect using NLA, trying with SSL"); tcp_disconnect(); neg_proto = PROTOCOL_SSL; goto retry; } /* do not use encryption when using TLS */ - fprintf(stderr, "Connection established using CredSSP.\n"); + logger(Core, Notice, "Connection established using CredSSP."); g_encryption = False; } #endif else if (data == PROTOCOL_RDP) { - fprintf(stderr, "Connection established using plain RDP.\n"); + logger(Core, Notice, "Connection established using plain RDP."); } else if (data != PROTOCOL_RDP) { tcp_disconnect(); - error("Unexpected protocol in negotiation response, got data = 0x%x.\n", - data); + logger(Protocol, Error, + "iso_connect(), unexpected protocol in negotiation response, got 0x%x", + data); return False; } diff --git a/licence.c b/licence.c index 08efd5e..3ee575d 100644 --- a/licence.c +++ b/licence.c @@ -171,18 +171,20 @@ licence_process_request(STREAM s) rdssl_rc4_set_key(&crypt_key, g_licence_key, 16); rdssl_rc4_crypt(&crypt_key, hwid, hwid, sizeof(hwid)); -#if WITH_DEBUG - DEBUG(("Sending licensing PDU (message type 0x%02x)\n", LICENCE_TAG_LICENCE_INFO)); -#endif + logger(Protocol, Debug, + "license_process_request(), sending licensing PDU (message type 0x%02x)", + LICENCE_TAG_LICENCE_INFO); + licence_info(null_data, null_data, licence_data, licence_size, hwid, signature); xfree(licence_data); return; } -#if WITH_DEBUG - DEBUG(("Sending licensing PDU (message type 0x%02x)\n", LICENCE_TAG_NEW_LICENCE_REQUEST)); -#endif + logger(Protocol, Debug, + "license_process_request(), sending licensing PDU (message type 0x%02x)", + LICENCE_TAG_NEW_LICENCE_REQUEST); + licence_send_new_licence_request(null_data, null_data, g_username, g_hostname); } @@ -225,7 +227,8 @@ licence_parse_platform_challange(STREAM s, uint8 ** token, uint8 ** signature) in_uint16_le(s, tokenlen); if (tokenlen != LICENCE_TOKEN_SIZE) { - error("token len %d\n", tokenlen); + logger(Protocol, Error, + "license_parse_platform_challenge(), tokenlen != LICENSE_TOKEN_SIZE"); return False; } @@ -328,19 +331,20 @@ licence_process_error_alert(STREAM s) switch (error_code) { case 0x6: // ERR_NO_LICENSE_SERVER - warning("License error alert from server: No license server\n"); + logger(Core, Notice, "License error alert from server: No license server"); break; case 0x8: // ERR_INVALID_CLIENT - warning("License error alert from server: Invalid client\n"); + logger(Core, Notice, "License error alert from server: Invalid client"); break; case 0x4: // ERR_INVALID_SCOPE case 0xb: // ERR_INVALID_PRODUCTID case 0xc: // ERR_INVALID_MESSAGE_LENGTH default: - warning("License error alert from server: code %u, state transition %u\n", - error_code, state_transition); + logger(Core, Notice, + "License error alert from server: code %u, state transition %u", + error_code, state_transition); break; } @@ -357,9 +361,8 @@ licence_process(STREAM s) in_uint8(s, tag); in_uint8s(s, 3); /* version, length */ -#if WITH_DEBUG - DEBUG(("Received licensing PDU (message type 0x%02x)\n", tag)); -#endif + logger(Protocol, Debug, "license_process(), processing licensing PDU (message type 0x%02x)", + tag); switch (tag) { @@ -382,6 +385,7 @@ licence_process(STREAM s) break; default: - unimpl("licence tag 0x%02x\n", tag); + logger(Protocol, Warning, + "license_process(), unhandled license PDU tag 0x%02", tag); } } diff --git a/lspci.c b/lspci.c index d66c77f..d0670dd 100644 --- a/lspci.c +++ b/lspci.c @@ -98,7 +98,7 @@ handle_child_line(const char *line, void *data) } else { - warning("lspci: Unrecoqnized line '%s'\n", line); + logger(Core, Warning, "handle_child_line(), Unrecognized lspci line '%s'", line); } return True; } @@ -119,7 +119,7 @@ lspci_process_line(const char *line, void *data) } else { - error("lspci protocol error: Invalid line '%s'\n", line); + logger(Core, Error, "lspci_process_line(), invlid line '%s'", line); } return True; } @@ -137,11 +137,6 @@ lspci_process(STREAM s) /* str_handle_lines requires null terminated strings */ buf = xmalloc(pkglen + 1); STRNCPY(buf, (char *) s->p, pkglen + 1); -#if 0 - printf("lspci recv:\n"); - hexdump(s->p, pkglen); -#endif - str_handle_lines(buf, &rest, lspci_process_line, NULL); xfree(buf); } @@ -166,11 +161,5 @@ lspci_send(const char *output) len = strlen(output); s = channel_init(lspci_channel, len); out_uint8p(s, output, len) s_mark_end(s); - -#if 0 - printf("lspci send:\n"); - hexdump(s->channel_hdr + 8, s->end - s->channel_hdr - 8); -#endif - channel_send(s, lspci_channel); } diff --git a/mcs.c b/mcs.c index 3ebca2a..53e5af9 100644 --- a/mcs.c +++ b/mcs.c @@ -100,7 +100,7 @@ mcs_recv_connect_response(STREAM mcs_data) in_uint8(s, result); if (result != 0) { - error("MCS connect: %d\n", result); + logger(Protocol, Error, "mcs_recv_connect_response(), result=%d", result); return False; } @@ -114,8 +114,7 @@ mcs_recv_connect_response(STREAM mcs_data) /* if (length > mcs_data->size) { - error("MCS data length %d, expected %d\n", length, - mcs_data->size); + logger(Protocol, Error, "mcs_recv_connect_response(), expected length=%d, got %d",length, mcs_data->size); length = mcs_data->size; } @@ -170,14 +169,14 @@ mcs_recv_aucf(uint16 * mcs_userid) in_uint8(s, opcode); if ((opcode >> 2) != MCS_AUCF) { - error("expected AUcf, got %d\n", opcode); + logger(Protocol, Error, "mcs_recv_aucf(), expected opcode AUcf, got %d", opcode); return False; } in_uint8(s, result); if (result != 0) { - error("AUrq: %d\n", result); + logger(Protocol, Error, "mcs_recv_aucf(), expected result 0, got %d", result); return False; } @@ -193,7 +192,7 @@ mcs_send_cjrq(uint16 chanid) { STREAM s; - DEBUG_RDP5(("Sending CJRQ for channel #%d\n", chanid)); + logger(Protocol, Debug, "mcs_send_cjrq(), chanid=%d", chanid); s = iso_init(5); @@ -219,14 +218,14 @@ mcs_recv_cjcf(void) in_uint8(s, opcode); if ((opcode >> 2) != MCS_CJCF) { - error("expected CJcf, got %d\n", opcode); + logger(Protocol, Error, "mcs_recv_cjcf(), expected opcode CJcf, got %d", opcode); return False; } in_uint8(s, result); if (result != 0) { - error("CJrq: %d\n", result); + logger(Protocol, Error, "mcs_recv_cjcf(), expected result 0, got %d", result); return False; } @@ -294,7 +293,7 @@ mcs_recv(uint16 * channel, uint8 * rdpver) { if (appid != MCS_DPUM) { - error("expected data, got %d\n", opcode); + logger(Protocol, Error, "mcs_recv(), expected data, got %d", opcode); } return NULL; } diff --git a/orders.c b/orders.c index 2185d06..48fa584 100644 --- a/orders.c +++ b/orders.c @@ -162,7 +162,8 @@ setup_brush(BRUSH * out_brush, BRUSH * in_brush) brush_data = cache_get_brush_data(colour_code, cache_idx); if ((brush_data == NULL) || (brush_data->data == NULL)) { - error("error getting brush data, style %x\n", out_brush->style); + logger(Graphics, Error, "setup_brush(), error getting brush data, style %x", + out_brush->style); out_brush->bd = NULL; memset(out_brush->pattern, 0, 8); } @@ -215,8 +216,8 @@ process_destblt(STREAM s, DESTBLT_ORDER * os, uint32 present, RD_BOOL delta) if (present & 0x10) in_uint8(s, os->opcode); - DEBUG(("DESTBLT(op=0x%x,x=%d,y=%d,cx=%d,cy=%d)\n", - os->opcode, os->x, os->y, os->cx, os->cy)); + logger(Graphics, Debug, "process_destblt(), op=0x%x, x=%d, y=%d, cx=%d, cy=%d", + os->opcode, os->x, os->y, os->cx, os->cy); ui_destblt(ROP2_S(os->opcode), os->x, os->y, os->cx, os->cy); } @@ -250,8 +251,10 @@ process_patblt(STREAM s, PATBLT_ORDER * os, uint32 present, RD_BOOL delta) rdp_parse_brush(s, &os->brush, present >> 7); - DEBUG(("PATBLT(op=0x%x,x=%d,y=%d,cx=%d,cy=%d,bs=%d,bg=0x%x,fg=0x%x)\n", os->opcode, os->x, - os->y, os->cx, os->cy, os->brush.style, os->bgcolour, os->fgcolour)); + logger(Graphics, Debug, + "process_patblt(), op=0x%x, x=%d, y=%d, cx=%d, cy=%d, bs=%d, bg=0x%x, fg=0x%x)", + os->opcode, os->x, os->y, os->cx, os->cy, os->brush.style, os->bgcolour, + os->fgcolour); setup_brush(&brush, &os->brush); @@ -284,8 +287,9 @@ process_screenblt(STREAM s, SCREENBLT_ORDER * os, uint32 present, RD_BOOL delta) if (present & 0x0040) rdp_in_coord(s, &os->srcy, delta); - DEBUG(("SCREENBLT(op=0x%x,x=%d,y=%d,cx=%d,cy=%d,srcx=%d,srcy=%d)\n", - os->opcode, os->x, os->y, os->cx, os->cy, os->srcx, os->srcy)); + logger(Graphics, Debug, + "process_screenblt(), op=0x%x, x=%d, y=%d, cx=%d, cy=%d, srcx=%d, srcy=%d)", + os->opcode, os->x, os->y, os->cx, os->cy, os->srcx, os->srcy); ui_screenblt(ROP2_S(os->opcode), os->x, os->y, os->cx, os->cy, os->srcx, os->srcy); } @@ -317,12 +321,12 @@ process_line(STREAM s, LINE_ORDER * os, uint32 present, RD_BOOL delta) rdp_parse_pen(s, &os->pen, present >> 7); - DEBUG(("LINE(op=0x%x,sx=%d,sy=%d,dx=%d,dy=%d,fg=0x%x)\n", - os->opcode, os->startx, os->starty, os->endx, os->endy, os->pen.colour)); + logger(Graphics, Debug, "process_line(), op=0x%x, sx=%d, sy=%d, dx=%d, dy=%d, fg=0x%x)", + os->opcode, os->startx, os->starty, os->endx, os->endy, os->pen.colour); if (os->opcode < 0x01 || os->opcode > 0x10) { - error("bad ROP2 0x%x\n", os->opcode); + logger(Graphics, Error, "process_line(), bad ROP2 0x%x", os->opcode); return; } @@ -364,7 +368,8 @@ process_rect(STREAM s, RECT_ORDER * os, uint32 present, RD_BOOL delta) os->colour = (os->colour & 0xff00ffff) | (i << 16); } - DEBUG(("RECT(x=%d,y=%d,cx=%d,cy=%d,fg=0x%x)\n", os->x, os->y, os->cx, os->cy, os->colour)); + logger(Graphics, Debug, "process_rect(), x=%d, y=%d, cx=%d, cy=%d, fg=0x%x", + os->x, os->y, os->cx, os->cy, os->colour); ui_rect(os->x, os->y, os->cx, os->cy, os->colour); } @@ -393,8 +398,8 @@ process_desksave(STREAM s, DESKSAVE_ORDER * os, uint32 present, RD_BOOL delta) if (present & 0x20) in_uint8(s, os->action); - DEBUG(("DESKSAVE(l=%d,t=%d,r=%d,b=%d,off=%d,op=%d)\n", - os->left, os->top, os->right, os->bottom, os->offset, os->action)); + logger(Graphics, Debug, "process_desksave(), l=%d, t=%d, r=%d, b=%d, off=%d, op=%d", + os->left, os->top, os->right, os->bottom, os->offset, os->action); width = os->right - os->left + 1; height = os->bottom - os->top + 1; @@ -441,8 +446,9 @@ process_memblt(STREAM s, MEMBLT_ORDER * os, uint32 present, RD_BOOL delta) if (present & 0x0100) in_uint16_le(s, os->cache_idx); - DEBUG(("MEMBLT(op=0x%x,x=%d,y=%d,cx=%d,cy=%d,id=%d,idx=%d)\n", - os->opcode, os->x, os->y, os->cx, os->cy, os->cache_id, os->cache_idx)); + logger(Graphics, Debug, + "process_memblt(), op=0x%x, x=%d, y=%d, cx=%d, cy=%d, id=%d, idx=%d", os->opcode, + os->x, os->y, os->cx, os->cy, os->cache_id, os->cache_idx); bitmap = cache_get_bitmap(os->cache_id, os->cache_idx); if (bitmap == NULL) @@ -499,9 +505,10 @@ process_triblt(STREAM s, TRIBLT_ORDER * os, uint32 present, RD_BOOL delta) if (present & 0x010000) in_uint16_le(s, os->unknown); - DEBUG(("TRIBLT(op=0x%x,x=%d,y=%d,cx=%d,cy=%d,id=%d,idx=%d,bs=%d,bg=0x%x,fg=0x%x)\n", + logger(Graphics, Debug, + "process_triblt(), op=0x%x, x=%d, y=%d, cx=%d, cy=%d, id=%d, idx=%d, bs=%d, bg=0x%x, fg=0x%x", os->opcode, os->x, os->y, os->cx, os->cy, os->cache_id, os->cache_idx, - os->brush.style, os->bgcolour, os->fgcolour)); + os->brush.style, os->bgcolour, os->fgcolour); bitmap = cache_get_bitmap(os->cache_id, os->cache_idx); if (bitmap == NULL) @@ -545,19 +552,13 @@ process_polygon(STREAM s, POLYGON_ORDER * os, uint32 present, RD_BOOL delta) in_uint8a(s, os->data, os->datasize); } - DEBUG(("POLYGON(x=%d,y=%d,op=0x%x,fm=%d,fg=0x%x,n=%d,sz=%d)\n", - os->x, os->y, os->opcode, os->fillmode, os->fgcolour, os->npoints, os->datasize)); - - DEBUG(("Data: ")); - - for (index = 0; index < os->datasize; index++) - DEBUG(("%02x ", os->data[index])); - - DEBUG(("\n")); + logger(Graphics, Debug, + "process_polygon(), x=%d, y=%d, op=0x%x, fm=%d, fg=0x%x, n=%d, sz=%d", os->x, os->y, + os->opcode, os->fillmode, os->fgcolour, os->npoints, os->datasize); if (os->opcode < 0x01 || os->opcode > 0x10) { - error("bad ROP2 0x%x\n", os->opcode); + logger(Graphics, Error, "process_polygon(), bad ROP2 0x%x", os->opcode); return; } @@ -587,7 +588,7 @@ process_polygon(STREAM s, POLYGON_ORDER * os, uint32 present, RD_BOOL delta) ui_polygon(os->opcode - 1, os->fillmode, points, os->npoints + 1, NULL, 0, os->fgcolour); else - error("polygon parse error\n"); + logger(Graphics, Error, "process_polygon(), polygon parse error"); xfree(points); } @@ -630,20 +631,14 @@ process_polygon2(STREAM s, POLYGON2_ORDER * os, uint32 present, RD_BOOL delta) in_uint8a(s, os->data, os->datasize); } - DEBUG(("POLYGON2(x=%d,y=%d,op=0x%x,fm=%d,bs=%d,bg=0x%x,fg=0x%x,n=%d,sz=%d)\n", + logger(Graphics, Debug, + "process_polygon2(), x=%d, y=%d, op=0x%x, fm=%d, bs=%d, bg=0x%x, fg=0x%x, n=%d, sz=%d)", os->x, os->y, os->opcode, os->fillmode, os->brush.style, os->bgcolour, os->fgcolour, - os->npoints, os->datasize)); - - DEBUG(("Data: ")); - - for (index = 0; index < os->datasize; index++) - DEBUG(("%02x ", os->data[index])); - - DEBUG(("\n")); + os->npoints, os->datasize); if (os->opcode < 0x01 || os->opcode > 0x10) { - error("bad ROP2 0x%x\n", os->opcode); + logger(Graphics, Error, "process_polygon2(), bad ROP2 0x%x", os->opcode); return; } @@ -675,7 +670,7 @@ process_polygon2(STREAM s, POLYGON2_ORDER * os, uint32 present, RD_BOOL delta) ui_polygon(os->opcode - 1, os->fillmode, points, os->npoints + 1, &brush, os->bgcolour, os->fgcolour); else - error("polygon2 parse error\n"); + logger(Graphics, Error, "process_polygon2(), polygon parse error"); xfree(points); } @@ -710,19 +705,12 @@ process_polyline(STREAM s, POLYLINE_ORDER * os, uint32 present, RD_BOOL delta) in_uint8a(s, os->data, os->datasize); } - DEBUG(("POLYLINE(x=%d,y=%d,op=0x%x,fg=0x%x,n=%d,sz=%d)\n", - os->x, os->y, os->opcode, os->fgcolour, os->lines, os->datasize)); - - DEBUG(("Data: ")); - - for (index = 0; index < os->datasize; index++) - DEBUG(("%02x ", os->data[index])); - - DEBUG(("\n")); + logger(Graphics, Debug, "process_polyline(), x=%d, y=%d, op=0x%x, fg=0x%x, n=%d, sz=%d)", + os->x, os->y, os->opcode, os->fgcolour, os->lines, os->datasize); if (os->opcode < 0x01 || os->opcode > 0x10) { - error("bad ROP2 0x%x\n", os->opcode); + logger(Graphics, Error, "process_polyline(), bad ROP2 0x%x", os->opcode); return; } @@ -753,7 +741,7 @@ process_polyline(STREAM s, POLYLINE_ORDER * os, uint32 present, RD_BOOL delta) if (next - 1 == os->lines) ui_polyline(os->opcode - 1, points, os->lines + 1, &pen); else - error("polyline parse error\n"); + logger(Graphics, Error, "process_polyline(), parse error"); xfree(points); } @@ -783,8 +771,9 @@ process_ellipse(STREAM s, ELLIPSE_ORDER * os, uint32 present, RD_BOOL delta) if (present & 0x40) rdp_in_colour(s, &os->fgcolour); - DEBUG(("ELLIPSE(l=%d,t=%d,r=%d,b=%d,op=0x%x,fm=%d,fg=0x%x)\n", os->left, os->top, - os->right, os->bottom, os->opcode, os->fillmode, os->fgcolour)); + logger(Graphics, Debug, + "process_ellipse(), l=%d, t=%d, r=%d, b=%d, op=0x%x, fm=%d, fg=0x%x", os->left, + os->top, os->right, os->bottom, os->opcode, os->fillmode, os->fgcolour); ui_ellipse(os->opcode - 1, os->fillmode, os->left, os->top, os->right - os->left, os->bottom - os->top, NULL, 0, os->fgcolour); @@ -822,9 +811,10 @@ process_ellipse2(STREAM s, ELLIPSE2_ORDER * os, uint32 present, RD_BOOL delta) rdp_parse_brush(s, &os->brush, present >> 8); - DEBUG(("ELLIPSE2(l=%d,t=%d,r=%d,b=%d,op=0x%x,fm=%d,bs=%d,bg=0x%x,fg=0x%x)\n", + logger(Graphics, Debug, + "process_ellipse2(), l=%d, t=%d, r=%d, b=%d, op=0x%x, fm=%d, bs=%d, bg=0x%x, fg=0x%x", os->left, os->top, os->right, os->bottom, os->opcode, os->fillmode, os->brush.style, - os->bgcolour, os->fgcolour)); + os->bgcolour, os->fgcolour); setup_brush(&brush, &os->brush); @@ -836,7 +826,6 @@ process_ellipse2(STREAM s, ELLIPSE2_ORDER * os, uint32 present, RD_BOOL delta) static void process_text2(STREAM s, TEXT2_ORDER * os, uint32 present, RD_BOOL delta) { - int i; BRUSH brush; if (present & 0x000001) @@ -895,14 +884,11 @@ process_text2(STREAM s, TEXT2_ORDER * os, uint32 present, RD_BOOL delta) in_uint8a(s, os->text, os->length); } - DEBUG(("TEXT2(x=%d,y=%d,cl=%d,ct=%d,cr=%d,cb=%d,bl=%d,bt=%d,br=%d,bb=%d,bs=%d,bg=0x%x,fg=0x%x,font=%d,fl=0x%x,op=0x%x,mix=%d,n=%d)\n", os->x, os->y, os->clipleft, os->cliptop, os->clipright, os->clipbottom, os->boxleft, os->boxtop, os->boxright, os->boxbottom, os->brush.style, os->bgcolour, os->fgcolour, os->font, os->flags, os->opcode, os->mixmode, os->length)); - - DEBUG(("Text: ")); - - for (i = 0; i < os->length; i++) - DEBUG(("%02x ", os->text[i])); - - DEBUG(("\n")); + logger(Graphics, Debug, + "process_text2(), x=%d, y=%d, cl=%d, ct=%d, cr=%d, cb=%d, bl=%d, bt=%d, br=%d, bb=%d, bs=%d, bg=0x%x, fg=0x%x, font=%d, fl=0x%x, op=0x%x, mix=%d, n=%d", + os->x, os->y, os->clipleft, os->cliptop, os->clipright, os->clipbottom, os->boxleft, + os->boxtop, os->boxright, os->boxbottom, os->brush.style, os->bgcolour, os->fgcolour, + os->font, os->flags, os->opcode, os->mixmode, os->length); setup_brush(&brush, &os->brush); @@ -933,7 +919,8 @@ process_raw_bmpcache(STREAM s) in_uint16_le(s, cache_idx); in_uint8p(s, data, bufsize); - DEBUG(("RAW_BMPCACHE(cx=%d,cy=%d,id=%d,idx=%d)\n", width, height, cache_id, cache_idx)); + logger(Graphics, Debug, "process_raw_bpmcache(), cx=%d, cy=%d, id=%d, idx=%d", width, + height, cache_id, cache_idx); inverted = (uint8 *) xmalloc(width * height * Bpp); for (y = 0; y < height; y++) { @@ -984,8 +971,10 @@ process_bmpcache(STREAM s) } in_uint8p(s, data, size); - - DEBUG(("BMPCACHE(cx=%d,cy=%d,id=%d,idx=%d,bpp=%d,size=%d,pad1=%d,bufsize=%d,pad2=%d,rs=%d,fs=%d)\n", width, height, cache_id, cache_idx, bpp, size, pad1, bufsize, pad2, row_size, final_size)); + logger(Graphics, Debug, + "process_bmpcache(), cx=%d, cy=%d, id=%d, idx=%d, bpp=%d, size=%d, pad1=%d, bufsize=%d, pad2=%d, rs=%d, fs=%d", + width, height, cache_id, cache_idx, bpp, size, pad1, bufsize, pad2, row_size, + final_size); bmpdata = (uint8 *) xmalloc(width * height * Bpp); @@ -996,7 +985,7 @@ process_bmpcache(STREAM s) } else { - DEBUG(("Failed to decompress bitmap data\n")); + logger(Graphics, Error, "process_bmpcache(), Failed to decompress bitmap data"); } xfree(bmpdata); @@ -1044,8 +1033,9 @@ process_bmpcache2(STREAM s, uint16 flags, RD_BOOL compressed) in_uint8p(s, data, bufsize); - DEBUG(("BMPCACHE2(compr=%d,flags=%x,cx=%d,cy=%d,id=%d,idx=%d,Bpp=%d,bs=%d)\n", - compressed, flags, width, height, cache_id, cache_idx, Bpp, bufsize)); + logger(Graphics, Debug, + "process_bmpcache2(), compr=%d, flags=%x, cx=%d, cy=%d, id=%d, idx=%d, Bpp=%d, bs=%d", + compressed, flags, width, height, cache_id, cache_idx, Bpp, bufsize); bmpdata = (uint8 *) xmalloc(width * height * Bpp); @@ -1053,7 +1043,8 @@ process_bmpcache2(STREAM s, uint16 flags, RD_BOOL compressed) { if (!bitmap_decompress(bmpdata, width, height, data, bufsize, Bpp)) { - DEBUG(("Failed to decompress bitmap data\n")); + logger(Graphics, Error, + "process_bmpcache2(), failed to decompress bitmap data"); xfree(bmpdata); return; } @@ -1076,7 +1067,7 @@ process_bmpcache2(STREAM s, uint16 flags, RD_BOOL compressed) } else { - DEBUG(("process_bmpcache2: ui_create_bitmap failed\n")); + logger(Graphics, Error, "process_bmpcache2(), ui_create_bitmap(), failed"); } xfree(bmpdata); @@ -1106,7 +1097,7 @@ process_colcache(STREAM s) in_uint8s(s, 1); /* pad */ } - DEBUG(("COLCACHE(id=%d,n=%d)\n", cache_id, map.ncolours)); + logger(Graphics, Debug, "process_colcache(), id=%d, n=%d", cache_id, map.ncolours); hmap = ui_create_colourmap(&map); @@ -1129,7 +1120,7 @@ process_fontcache(STREAM s) in_uint8(s, font); in_uint8(s, nglyphs); - DEBUG(("FONTCACHE(font=%d,n=%d)\n", font, nglyphs)); + logger(Graphics, Debug, "process_fontcache(), font=%d, n=%d", font, nglyphs); for (i = 0; i < nglyphs; i++) { @@ -1197,7 +1188,8 @@ process_brushcache(STREAM s, uint16 flags) in_uint8(s, type); /* type, 0x8x = cached */ in_uint8(s, size); - DEBUG(("BRUSHCACHE(idx=%d,wd=%d,ht=%d,sz=%d)\n", cache_idx, width, height, size)); + logger(Graphics, Debug, "process_brushcache(), idx=%d, wd=%d, ht=%d, type=0x%x sz=%d", + cache_idx, width, height, type, size); if ((width == 8) && (height == 8)) { @@ -1216,8 +1208,9 @@ process_brushcache(STREAM s, uint16 flags) } else { - warning("incompatible brush, colour_code %d size %d\n", colour_code, - size); + logger(Graphics, Warning, + "process_brushcache(), incompatible brush, colour_code %d size %d", + colour_code, size); } cache_put_brush_data(1, cache_idx, &brush_data); } @@ -1240,12 +1233,16 @@ process_brushcache(STREAM s, uint16 flags) } else { - warning("incompatible brush, colour_code %d size %d\n", colour_code, size); + logger(Graphics, Warning, + "process_brushcache(), incompatible brush, colour_code %d size %d", + colour_code, size); } } else { - warning("incompatible brush, width height %d %d\n", width, height); + logger(Graphics, Warning, + "process_brushcache(), incompatible brush, width height %d %d", width, + height); } } @@ -1298,7 +1295,8 @@ process_secondary_order(STREAM s) break; default: - unimpl("secondary order %d\n", type); + logger(Graphics, Warning, + "process_secondary_order(), unhandled secondary order %d", type); } s->p = next_order; @@ -1320,7 +1318,7 @@ process_orders(STREAM s, uint16 num_orders) if (!(order_flags & RDP_ORDER_STANDARD)) { - error("order parsing failed\n"); + logger(Graphics, Error, "process_orders(), order parsing failed"); break; } @@ -1429,7 +1427,9 @@ process_orders(STREAM s, uint16 num_orders) break; default: - unimpl("order %d\n", os->order_type); + logger(Graphics, Warning, + "process_orders(), unhandled order type %d", + os->order_type); return; } @@ -1442,7 +1442,8 @@ process_orders(STREAM s, uint16 num_orders) #if 0 /* not true when RDP_COMPRESSION is set */ if (s->p != g_next_packet) - error("%d bytes remaining\n", (int) (g_next_packet - s->p)); + logger(Graphics, Error, "process_orders(), %d bytes remaining", + (int) (g_next_packet - s->p)); #endif } diff --git a/parallel.c b/parallel.c index a4eb356..f74bede 100644 --- a/parallel.c +++ b/parallel.c @@ -60,7 +60,7 @@ parallel_enum_devices(uint32 * id, char *optarg) g_rdpdr_device[*id].local_path = xmalloc(strlen(pos2) + 1); strcpy(g_rdpdr_device[*id].local_path, pos2); - printf("PARALLEL %s to %s\n", optarg, pos2); + logger(Core, Debug, "parallell_enum_devices(), %s to %s", optarg, pos2); /* set device type */ g_rdpdr_device[*id].device_type = DEVICE_TYPE_PARALLEL; @@ -83,13 +83,13 @@ parallel_create(uint32 device_id, uint32 access, uint32 share_mode, uint32 dispo parallel_fd = open(g_rdpdr_device[device_id].local_path, O_RDWR); if (parallel_fd == -1) { - perror("open"); + logger(Core, Error, "parallell_create(), open failed: %s", strerror(errno)); return RD_STATUS_ACCESS_DENIED; } /* all read and writes should be non blocking */ if (fcntl(parallel_fd, F_SETFL, O_NONBLOCK) == -1) - perror("fcntl"); + logger(Core, Error, "parallell_create(), fcntl failed: %s", strerror(errno)); #if defined(LPABORT) /* Retry on errors */ @@ -147,8 +147,7 @@ parallel_write(RD_NTHANDLE handle, uint8 * data, uint32 length, uint32 offset, u #if defined(LPGETSTATUS) if (ioctl(handle, LPGETSTATUS, &status) == 0) { - /* coming soon: take care for the printer status */ - printf("parallel_write: status = %d, errno = %d\n", status, errno); + logger(Core, Error, "parellel_write(), ioctl failed: %s", strerror(errno)); } #endif } @@ -166,16 +165,15 @@ parallel_device_control(RD_NTHANDLE handle, uint32 request, STREAM in, STREAM ou request >>= 2; request &= 0xfff; - printf("PARALLEL IOCTL %d: ", request); + logger(Protocol, Debug, "parallel_device_control(), ioctl %d", request); switch (request) { case IOCTL_PAR_QUERY_RAW_DEVICE_ID: default: - - printf("\n"); - unimpl("UNKNOWN IOCTL %d\n", request); + logger(Protocol, Warning, "parallel_device_control(), unhandled ioctl %d", + request); } return RD_STATUS_SUCCESS; } diff --git a/printer.c b/printer.c index 237c4cf..06a1e95 100644 --- a/printer.c +++ b/printer.c @@ -87,8 +87,8 @@ printer_enum_devices(uint32 * id, char *optarg) strcpy(pprinter_data->driver, pos2); } - printf("PRINTER %s to %s driver %s\n", g_rdpdr_device[*id].name, - pprinter_data->printer, pprinter_data->driver); + logger(Core, Debug, "printer_enum_devices(), %s to %s driver %s", + g_rdpdr_device[*id].name, pprinter_data->printer, pprinter_data->driver); g_rdpdr_device[*id].device_type = DEVICE_TYPE_PRINTER; g_rdpdr_device[*id].pdevice_data = (void *) pprinter_data; count++; diff --git a/printercache.c b/printercache.c index 252ed1c..e0a449c 100644 --- a/printercache.c +++ b/printercache.c @@ -3,7 +3,7 @@ Entrypoint and utility functions Copyright (C) Matthew Chapman 1999-2008 Copyright (C) Jeroen Meijer 2003-2008 - Copyright (C) Henrik Andersson 2013 + Copyright (C) Henrik Andersson 2013-2017 This program is free software: you can redistribute it and/or modify @@ -47,7 +47,7 @@ printercache_mkdir(char *base, char *printer) sprintf(path, "%s/.rdesktop", base); if ((mkdir(path, 0700) == -1) && errno != EEXIST) { - perror(path); + logger(Core, Error, "printercache_mkdir(), mkdir() failed: %s", strerror(errno)); xfree(path); return False; } @@ -55,7 +55,7 @@ printercache_mkdir(char *base, char *printer) strcat(path, "/rdpdr"); if ((mkdir(path, 0700) == -1) && errno != EEXIST) { - perror(path); + logger(Core, Error, "printercache_mkdir(), mkdir() failed: %s", strerror(errno)); xfree(path); return False; } @@ -64,7 +64,7 @@ printercache_mkdir(char *base, char *printer) strcat(path, printer); if ((mkdir(path, 0700) == -1) && errno != EEXIST) { - perror(path); + logger(Core, Error, "printercache_mkdir(), mkdir() failed: %s", strerror(errno)); xfree(path); return False; } @@ -137,9 +137,12 @@ printercache_rename_blob(char *printer, char *new_printer) sprintf(printer_path, "%s/.rdesktop/rdpdr/%s", home, printer); sprintf(new_printer_path, "%s/.rdesktop/rdpdr/%s", home, new_printer); - printf("%s,%s\n", printer_path, new_printer_path); + logger(Core, Debug, "printercache_rename_blob(), printer_path=%s, new_printer_path=%s", + printer_path, new_printer_path); if (rename(printer_path, new_printer_path) < 0) { + logger(Core, Error, "printercache_rename_blob(), rename() failed: %s", + strerror(errno)); xfree(printer_path); xfree(new_printer_path); return False; @@ -214,14 +217,15 @@ printercache_save_blob(char *printer_name, uint8 * data, uint32 length) fd = open(path, O_WRONLY | O_CREAT | O_TRUNC, 0600); if (fd == -1) { - perror(path); + logger(Core, Error, "printercache_save_blob(), open() failed: %s", strerror(errno)); xfree(path); return; } if (write(fd, data, length) != length) { - perror(path); + logger(Core, Error, "printercache_save_blob(), write() failed: %s", + strerror(errno)); unlink(path); } @@ -304,8 +308,8 @@ printercache_process(STREAM s) driver_length + printer_length + 19); break; default: - - unimpl("RDPDR Printer Cache Packet Type: %d\n", type); + logger(Protocol, Warning, + "printercache_process(), unhandled packet type %d", type); break; } } diff --git a/proto.h b/proto.h index 3bb02a5..9164e8e 100644 --- a/proto.h +++ b/proto.h @@ -24,12 +24,6 @@ extern "C" { #endif /* *INDENT-ON* */ -/* utils.c */ -char *utils_string_escape(const char *str); -char *utils_string_unescape(const char *str); -int utils_locale_to_utf8(const char *src, size_t is, char *dest, size_t os); -int utils_mkdir_safe(const char *path, int mask); -int utils_mkdir_p(const char *path, int mask); /* bitmap.c */ RD_BOOL bitmap_decompress(uint8 * output, int width, int height, uint8 * input, int size, int Bpp); /* cache.c */ @@ -131,9 +125,6 @@ void exit_if_null(void *ptr); char *xstrdup(const char *s); void *xrealloc(void *oldmem, size_t size); void xfree(void *mem); -void error(char *format, ...); -void warning(char *format, ...); -void unimpl(char *format, ...); void hexdump(unsigned char *p, unsigned int len); char *next_arg(char *src, char needle); void toupper_str(char *p); diff --git a/pstcache.c b/pstcache.c index 35a8684..6167723 100644 --- a/pstcache.c +++ b/pstcache.c @@ -70,7 +70,8 @@ pstcache_load_bitmap(uint8 cache_id, uint16 cache_idx) rd_read_file(fd, celldata, cellhdr.length); bitmap = ui_create_bitmap(cellhdr.width, cellhdr.height, celldata); - DEBUG(("Load bitmap from disk: id=%d, idx=%d, bmp=%p)\n", cache_id, cache_idx, bitmap)); + logger(Core, Debug, "pstcache_load_bitmap(), load bitmap from disk: id=%d, idx=%d, bmp=%p)", + cache_id, cache_idx, bitmap); cache_put_bitmap(cache_id, cache_idx, bitmap); xfree(celldata); @@ -119,7 +120,7 @@ pstcache_enumerate(uint8 id, HASH_KEY * keylist) if (g_pstcache_enumerated) return 0; - DEBUG_RDP5(("Persistent bitmap cache enumeration... ")); + logger(Core, Debug, "pstcache_enumerate(), start enumeration"); for (idx = 0; idx < BMPCACHE2_NUM_PSTCELLS; idx++) { fd = g_pstcache_fd[id]; @@ -151,7 +152,7 @@ pstcache_enumerate(uint8 id, HASH_KEY * keylist) } } - DEBUG_RDP5(("%d cached bitmaps.\n", idx)); + logger(Core, Debug, "pstcache_enumerate(), %d cached bitmaps", idx); cache_rebuild_bmpcache_linked_list(id, mru_idx, idx); g_pstcache_enumerated = True; @@ -175,13 +176,14 @@ pstcache_init(uint8 cache_id) if (!rd_pstcache_mkdir()) { - DEBUG(("failed to get/make cache directory!\n")); + logger(Core, Error, + "pstcache_init(), failed to get/make cache directory, disabling feature"); return False; } g_pstcache_Bpp = (g_server_depth + 7) / 8; sprintf(filename, "cache/pstcache_%d_%d", cache_id, g_pstcache_Bpp); - DEBUG(("persistent bitmap cache file: %s\n", filename)); + logger(Core, Debug, "pstcache_init(), bitmap cache file %s", filename); fd = rd_open_file(filename); if (fd == -1) @@ -189,7 +191,8 @@ pstcache_init(uint8 cache_id) if (!rd_lock_file(fd, 0, 0)) { - warning("Persistent bitmap caching is disabled. (The file is already in use)\n"); + logger(Core, Error, + "pstcache_init(), failed to lock persistent cache file, disabling feature"); rd_close_file(fd); return False; } diff --git a/rdesktop.c b/rdesktop.c index 15031a6..9ba3c2b 100644 --- a/rdesktop.c +++ b/rdesktop.c @@ -3,7 +3,7 @@ Entrypoint and utility functions Copyright (C) Matthew Chapman 1999-2008 Copyright 2002-2011 Peter Astrand for Cendio AB - Copyright 2010-2016 Henrik Andersson for Cendio AB + Copyright 2010-2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -31,6 +31,7 @@ #include #include #include + #include "rdesktop.h" #ifdef HAVE_LOCALE_H @@ -262,6 +263,7 @@ usage(char *program) fprintf(stderr, " sc-card-name Specifies the card name of the smartcard to use\n"); #endif + fprintf(stderr, " -v: enable verbose logging\n"); fprintf(stderr, "\n"); @@ -532,6 +534,9 @@ main(int argc, char *argv[]) char *rdpsnd_optarg = NULL; #endif + /* setup debug logging from environment */ + logger_set_subjects(getenv("RDESKTOP_DEBUG")); + #ifdef HAVE_LOCALE_H /* Set locale according to environment */ locale = setlocale(LC_ALL, ""); @@ -566,7 +571,7 @@ main(int argc, char *argv[]) #define VNCOPT #endif while ((c = getopt(argc, argv, - VNCOPT "A:u:L:d:s:c:p:n:k:g:o:fbBeEitmzCDKS:T:NX:a:x:Pr:045h?")) != -1) + VNCOPT "A:u:L:d:s:c:p:n:k:g:o:fbBeEitmzCDKS:T:NX:a:x:Pr:045vh?")) != -1) { switch (c) { @@ -657,7 +662,7 @@ main(int argc, char *argv[]) g_width = strtol(optarg, &p, 10); if (g_width <= 0) { - error("invalid geometry\n"); + logger(Core, Error, "invalid geometry width specified"); return EX_USAGE; } @@ -666,7 +671,7 @@ main(int argc, char *argv[]) if (g_height <= 0) { - error("invalid geometry\n"); + logger(Core, Error, "invalid geometry heigth specified"); return EX_USAGE; } @@ -746,7 +751,7 @@ main(int argc, char *argv[]) if (*p) { - error("invalid button size\n"); + logger(Core, Error, "invalid button size"); return EX_USAGE; } @@ -771,13 +776,14 @@ main(int argc, char *argv[]) g_server_depth != 15 && g_server_depth != 24 && g_server_depth != 32) { - error("Invalid server colour depth.\n"); + logger(Core, Error, + "Invalid server colour depth specified"); return EX_USAGE; } break; case 'z': - DEBUG(("rdp compression enabled\n")); + logger(Core, Debug, "rdp compression enabled"); flags |= (RDP_INFO_COMPRESSION | RDP_INFO_COMPRESSION2); break; @@ -835,14 +841,16 @@ main(int argc, char *argv[]) } #else - warning("Not compiled with sound support\n"); + logger(Core, Warning, + "Not compiled with sound support"); #endif if (str_startswith(optarg, "off")) #ifdef WITH_RDPSND g_rdpsnd = False; #else - warning("Not compiled with sound support\n"); + logger(Core, Warning, + "Not compiled with sound support"); #endif optarg = p; @@ -853,7 +861,8 @@ main(int argc, char *argv[]) #ifdef WITH_RDPSND g_rdpsnd = True; #else - warning("Not compiled with sound support\n"); + logger(Core, Warning, + "Not compiled with sound support"); #endif } } @@ -904,12 +913,15 @@ main(int argc, char *argv[]) #ifdef WITH_SCARD scard_enum_devices(&g_num_devices, optarg + 5); #else - warning("Not compiled with smartcard support\n"); + logger(Core, Warning, + "Not compiled with smartcard support\n"); #endif } else { - warning("Unknown -r argument\n\n\tPossible arguments are: comport, disk, lptport, printer, sound, clipboard, scard\n"); + logger(Core, Warning, + "Unknown -r argument '%s'. Possible arguments are: comport, disk, lptport, printer, sound, clipboard, scard", + optarg); } break; @@ -930,7 +942,9 @@ main(int argc, char *argv[]) char *p = strchr(optarg, '='); if (p == NULL) { - warning("Skipping option '%s' specified, lacks name=value format.\n", optarg); + logger(Core, Warning, + "Skipping specified option '%s', lacks name=value format", + optarg); continue; } @@ -953,6 +967,9 @@ main(int argc, char *argv[]) } break; #endif + case 'v': + logger_set_verbose(1); + break; case 'h': case '?': default: @@ -979,33 +996,33 @@ main(int argc, char *argv[]) if (g_win_button_size) { - error("You cannot use -S and -A at the same time\n"); + logger(Core, Error, "You cannot use -S and -A at the same time"); return EX_USAGE; } g_rdp5_performanceflags &= ~PERF_DISABLE_FULLWINDOWDRAG; if (geometry_option) { - error("You cannot use -g and -A at the same time\n"); + logger(Core, Error, "You cannot use -g and -A at the same time"); return EX_USAGE; } if (g_fullscreen) { - error("You cannot use -f and -A at the same time\n"); + logger(Core, Error, "You cannot use -f and -A at the same time"); return EX_USAGE; } if (g_hide_decorations) { - error("You cannot use -D and -A at the same time\n"); + logger(Core, Error, "You cannot use -D and -A at the same time"); return EX_USAGE; } if (g_embed_wnd) { - error("You cannot use -X and -A at the same time\n"); + logger(Core, Error, "You cannot use -X and -A at the same time"); return EX_USAGE; } if (g_rdp_version < RDP_V5) { - error("You cannot use -4 and -A at the same time\n"); + logger(Core, Error, "You cannot use -4 and -A at the same time"); return EX_USAGE; } g_sizeopt = -100; @@ -1017,7 +1034,8 @@ main(int argc, char *argv[]) pw = getpwuid(getuid()); if ((pw == NULL) || (pw->pw_name == NULL)) { - error("could not determine username, use -u\n"); + logger(Core, Error, + "could not determine username, use -u to set one"); return EX_OSERR; } /* +1 for trailing \0 */ @@ -1042,7 +1060,7 @@ main(int argc, char *argv[]) { if (gethostname(fullhostname, sizeof(fullhostname)) == -1) { - error("could not determine local hostname, use -n\n"); + logger(Core, Error, "could not determine local hostname, use -n\n"); return EX_OSERR; } @@ -1057,7 +1075,8 @@ main(int argc, char *argv[]) { if (locale && xkeymap_from_locale(locale)) { - fprintf(stderr, "Autoselected keyboard map %s\n", g_keymapname); + logger(Core, Notice, "Autoselecting keyboard map '%s' from locale", + g_keymapname); } else { @@ -1087,19 +1106,19 @@ main(int argc, char *argv[]) { if (ctrl_init(server, domain, g_username) < 0) { - error("Failed to initialize ctrl mode."); + logger(Core, Error, "Failed to initialize ctrl mode"); exit(1); } if (ctrl_is_slave()) { - fprintf(stdout, - "rdesktop in slave mode sending command to master process.\n"); + logger(Core, Notice, + "rdesktop in slave mode sending command to master process"); if (g_seamless_spawn_cmd[0]) return ctrl_send_command("seamless.spawn", g_seamless_spawn_cmd); - fprintf(stdout, "No command specified to be spawn in seamless mode.\n"); + logger(Core, Notice, "No command specified to be spawned in seamless mode"); return EX_USAGE; } } @@ -1109,7 +1128,7 @@ main(int argc, char *argv[]) #ifdef WITH_RDPSND if (!rdpsnd_init(rdpsnd_optarg)) - warning("Initializing sound-support failed!\n"); + logger(Core, Warning, "Initializing sound-support failed"); #endif if (g_lspci_enabled) @@ -1130,8 +1149,8 @@ main(int argc, char *argv[]) STRNCPY(server, g_redirect_server, sizeof(server)); flags |= RDP_INFO_AUTOLOGON; - fprintf(stderr, "Redirected to %s@%s session %d.\n", - g_redirect_username, g_redirect_server, g_redirect_session_id); + logger(Core, Notice, "Redirected to %s@%s session %d.", + g_redirect_username, g_redirect_server, g_redirect_session_id); /* A redirect on SSL from a 2003 WTS will result in a 'connection reset by peer' and therefor we just clear this error before we connect to redirected server. @@ -1153,8 +1172,9 @@ main(int argc, char *argv[]) /* check if auto reconnect cookie has timed out */ if (time(NULL) - g_reconnect_random_ts > RECONNECT_TIMEOUT) { - fprintf(stderr, "Tried to reconnect for %d minutes, giving up.\n", - RECONNECT_TIMEOUT / 60); + logger(Core, Notice, + "Tried to reconnect for %d minutes, giving up.", + RECONNECT_TIMEOUT / 60); return EX_PROTOCOL; } @@ -1173,7 +1193,7 @@ main(int argc, char *argv[]) if (!g_packet_encryption) g_encryption_initial = g_encryption = False; - DEBUG(("Connection successful.\n")); + logger(Core, Verbose, "Connection successful"); rd_create_ui(); tcp_run_ui(True); @@ -1184,7 +1204,7 @@ main(int argc, char *argv[]) tcp_run_ui(False); - DEBUG(("Disconnecting...\n")); + logger(Core, Verbose, "Disconnecting..."); rdp_disconnect(); if (g_redirect) @@ -1193,9 +1213,9 @@ main(int argc, char *argv[]) /* handle network error and start autoreconnect */ if (g_network_error && !deactivated) { - fprintf(stderr, - "Disconnected due to network error, retrying to reconnect for %d minutes.\n", - RECONNECT_TIMEOUT / 60); + logger(Core, Notice, + "Disconnected due to network error, retrying to reconnect for %d minutes.", + RECONNECT_TIMEOUT / 60); g_network_error = False; g_reconnect_loop = True; continue; @@ -1319,7 +1339,7 @@ xmalloc(int size) void *mem = malloc(size); if (mem == NULL) { - error("xmalloc %d\n", size); + logger(Core, Error, "xmalloc, failed to allocate %d bytes", size); exit(EX_UNAVAILABLE); } return mem; @@ -1331,7 +1351,7 @@ exit_if_null(void *ptr) { if (ptr == NULL) { - error("unexpected null pointer. Out of memory?\n"); + logger(Core, Error, "unexpected null pointer. Out of memory?"); exit(EX_UNAVAILABLE); } } @@ -1343,7 +1363,7 @@ xstrdup(const char *s) char *mem = strdup(s); if (mem == NULL) { - perror("strdup"); + logger(Core, Error, "xstrdup(), strdup() failed: %s", strerror(errno)); exit(EX_UNAVAILABLE); } return mem; @@ -1360,7 +1380,7 @@ xrealloc(void *oldmem, size_t size) mem = realloc(oldmem, size); if (mem == NULL) { - error("xrealloc %ld\n", size); + logger(Core, Error, "xrealloc, failed to reallocate %ld bytes", size); exit(EX_UNAVAILABLE); } return mem; @@ -1373,45 +1393,6 @@ xfree(void *mem) free(mem); } -/* report an error */ -void -error(char *format, ...) -{ - va_list ap; - - fprintf(stderr, "ERROR: "); - - va_start(ap, format); - vfprintf(stderr, format, ap); - va_end(ap); -} - -/* report a warning */ -void -warning(char *format, ...) -{ - va_list ap; - - fprintf(stderr, "WARNING: "); - - va_start(ap, format); - vfprintf(stderr, format, ap); - va_end(ap); -} - -/* report an unimplemented protocol feature */ -void -unimpl(char *format, ...) -{ - va_list ap; - - fprintf(stderr, "NOT IMPLEMENTED: "); - - va_start(ap, format); - vfprintf(stderr, format, ap); - va_end(ap); -} - /* produce a hex dump */ void hexdump(unsigned char *p, unsigned int len) @@ -1600,13 +1581,13 @@ subprocess(char *const argv[], str_handle_lines_t linehandler, void *data) if (pipe(fd) < 0) { - perror("pipe"); + logger(Core, Error, "subprocess(), pipe() failed: %s", strerror(errno)); return False; } if ((child = fork()) < 0) { - perror("fork"); + logger(Core, Error, "subprocess(), fork() failed: %s", strerror(errno)); return False; } @@ -1622,7 +1603,7 @@ subprocess(char *const argv[], str_handle_lines_t linehandler, void *data) /* Execute */ execvp(argv[0], argv); - perror("Error executing child"); + logger(Core, Error, "subprocess(), execvp() failed: %s", strerror(errno)); _exit(128); } @@ -1733,7 +1714,7 @@ save_licence(unsigned char *data, int length) path[sizeof(path) - 1] = '\0'; if (utils_mkdir_p(path, 0700) == -1) { - perror(path); + logger(Core, Error, "save_license(), utils_mkdir_p() failed: %s", strerror(errno)); return; } @@ -1753,18 +1734,18 @@ save_licence(unsigned char *data, int length) fd = open(tmppath, O_WRONLY | O_CREAT | O_TRUNC, 0600); if (fd == -1) { - perror(tmppath); + logger(Core, Error, "save_license(), open() failed: %s", strerror(errno)); return; } if (write(fd, data, length) != length) { - perror(tmppath); + logger(Core, Error, "save_license(), write() failed: %s", strerror(errno)); unlink(tmppath); } else if (rename(tmppath, path) == -1) { - perror(path); + logger(Core, Error, "save_license(), rename() failed: %s", strerror(errno)); unlink(tmppath); } @@ -1799,7 +1780,7 @@ rd_pstcache_mkdir(void) if ((mkdir(bmpcache_dir, S_IRWXU) == -1) && errno != EEXIST) { - perror(bmpcache_dir); + logger(Core, Error, "rd_pstcache_mkdir(), mkdir() failed: %s", strerror(errno)); return False; } @@ -1807,7 +1788,7 @@ rd_pstcache_mkdir(void) if ((mkdir(bmpcache_dir, S_IRWXU) == -1) && errno != EEXIST) { - perror(bmpcache_dir); + logger(Core, Error, "rd_pstcache_mkdir(), mkdir() failed: %s", strerror(errno)); return False; } @@ -1828,7 +1809,8 @@ rd_open_file(char *filename) sprintf(fn, "%s/.rdesktop/%s", home, filename); fd = open(fn, O_RDWR | O_CREAT, S_IRUSR | S_IWUSR); if (fd == -1) - perror(fn); + logger(Core, Error, "rd_open_file(), open() failed: %s", strerror(errno)); + return fd; } diff --git a/rdesktop.h b/rdesktop.h index e0380f5..f24f39c 100644 --- a/rdesktop.h +++ b/rdesktop.h @@ -120,48 +120,6 @@ #define EXRD_WINDOW_CLOSED 62 #define EXRD_UNKNOWN 63 -#ifdef WITH_DEBUG -#define DEBUG(args) printf args; -#else -#define DEBUG(args) -#endif - -#ifdef WITH_DEBUG_KBD -#define DEBUG_KBD(args) printf args; -#else -#define DEBUG_KBD(args) -#endif - -#ifdef WITH_DEBUG_RDP5 -#define DEBUG_RDP5(args) printf args; -#else -#define DEBUG_RDP5(args) -#endif - -#ifdef WITH_DEBUG_CLIPBOARD -#define DEBUG_CLIPBOARD(args) printf args; -#else -#define DEBUG_CLIPBOARD(args) -#endif - -#ifdef WITH_DEBUG_SOUND -#define DEBUG_SOUND(args) printf args; -#else -#define DEBUG_SOUND(args) -#endif - -#ifdef WITH_DEBUG_CHANNEL -#define DEBUG_CHANNEL(args) printf args; -#else -#define DEBUG_CHANNEL(args) -#endif - -#ifdef WITH_DEBUG_SCARD -#define DEBUG_SCARD(args) printf args; -#else -#define DEBUG_SCARD(args) -#endif - #define STRNCPY(dst,src,n) { strncpy(dst,src,n-1); dst[n-1] = 0; } #ifndef MIN @@ -209,6 +167,7 @@ #endif #endif +#include "utils.h" #include "parse.h" #include "constants.h" #include "types.h" diff --git a/rdp.c b/rdp.c index 1b5a68c..1f7d52a 100644 --- a/rdp.c +++ b/rdp.c @@ -78,10 +78,7 @@ extern char g_reconnect_random[16]; extern time_t g_reconnect_random_ts; extern RD_BOOL g_has_reconnect_random; extern uint8 g_client_random[SEC_RANDOM_SIZE]; - -#if WITH_DEBUG static uint32 g_packetno; -#endif /* Receive an RDP packet */ static STREAM @@ -129,10 +126,7 @@ rdp_recv(uint8 * type) in_uint8s(rdp_s, 2); /* userid */ *type = pdu_type & 0xf; -#if WITH_DEBUG - DEBUG(("RDP packet #%d, (type %x)\n", ++g_packetno, *type)); - hexdump(g_next_packet, length); -#endif /* */ + logger(Protocol, Debug, "rdp_recv(), RDP packet #%d, type 0x%x", ++g_packetno, *type); g_next_packet += length; return rdp_s; @@ -204,8 +198,8 @@ rdp_out_unistr(STREAM s, char *string, int len) icv_local_to_utf16 = iconv_open(WINDOWS_CODEPAGE, g_codepage); if (icv_local_to_utf16 == (iconv_t) - 1) { - error("rdp_out_unistr: iconv_open[%s -> %s] fail %p\n", - g_codepage, WINDOWS_CODEPAGE, icv_local_to_utf16); + logger(Protocol, Error, "rdo_out_unistr(), iconv_open[%s -> %s] fail %p", + g_codepage, WINDOWS_CODEPAGE, icv_local_to_utf16); abort(); } } @@ -221,7 +215,7 @@ rdp_out_unistr(STREAM s, char *string, int len) if (iconv(icv_local_to_utf16, (char **) &pin, &ibl, &pout, &obl) == (size_t) - 1) { - error("rdp_out_unistr: iconv(2) fail, errno %d\n", errno); + logger(Protocol, Error, "rdp_out_unistr(), iconv(2) fail, errno %d", errno); abort(); } @@ -245,8 +239,8 @@ rdp_in_unistr(STREAM s, int in_len, char **string, uint32 * str_size) icv_utf16_to_local = iconv_open(g_codepage, WINDOWS_CODEPAGE); if (icv_utf16_to_local == (iconv_t) - 1) { - error("rdp_in_unistr: iconv_open[%s -> %s] fail %p\n", - WINDOWS_CODEPAGE, g_codepage, icv_utf16_to_local); + logger(Protocol, Error, "rdp_in_unistr(), iconv_open[%s -> %s] fail %p", + WINDOWS_CODEPAGE, g_codepage, icv_utf16_to_local); abort(); } } @@ -268,11 +262,12 @@ rdp_in_unistr(STREAM s, int in_len, char **string, uint32 * str_size) { if (errno == E2BIG) { - warning("server sent an unexpectedly long string, truncating\n"); + logger(Protocol, Warning, + "rdp_in_unistr(), server sent an unexpectedly long string, truncating"); } else { - warning("rdp_in_unistr: iconv fail, errno %d\n", errno); + logger(Protocol, Warning, "rdp_in_unistr(), iconv fail, errno %d", errno); free(*string); *string = NULL; @@ -317,7 +312,7 @@ rdp_send_logon_info(uint32 flags, char *domain, char *user, if (g_rdp_version == RDP_V4 || 1 == g_server_rdp_version) { - DEBUG_RDP5(("Sending RDP4-style Logon packet\n")); + logger(Protocol, Debug, "rdp_send_logon_info(), sending RDP4-style Logon packet"); s = sec_init(sec_flags, 18 + len_domain + len_user + len_password + len_program + len_directory + 10); @@ -339,7 +334,7 @@ rdp_send_logon_info(uint32 flags, char *domain, char *user, else { - DEBUG_RDP5(("Sending RDP5-style Logon packet\n")); + logger(Protocol, Debug, "rdp_send_logon_info(), sending RDP5-style Logon packet"); if (g_redirect == True && g_redirect_cookie_len > 0) { @@ -383,7 +378,9 @@ rdp_send_logon_info(uint32 flags, char *domain, char *user, s = sec_init(sec_flags, packetlen); - DEBUG_RDP5(("Called sec_init with packetlen %d\n", packetlen)); + + logger(Protocol, Debug, "rdp_send_logon_info(), called sec_init with packetlen %d", + packetlen); /* TS_INFO_PACKET */ out_uint32(s, 0); /* Code Page */ @@ -952,7 +949,9 @@ rdp_process_bitmap_caps(STREAM s) in_uint16_le(s, width); in_uint16_le(s, height); - DEBUG(("setting desktop size and depth to: %dx%dx%d\n", width, height, depth)); + logger(Protocol, Debug, + "rdp_process_bitmap_caps(), setting desktop size and depth to: %dx%dx%d", width, + height, depth); /* * The server may limit depth and change the size of the desktop (for @@ -960,14 +959,16 @@ rdp_process_bitmap_caps(STREAM s) */ if (g_server_depth != depth) { - warning("Remote desktop does not support colour depth %d; falling back to %d\n", - g_server_depth, depth); + logger(Core, Verbose, + "Remote desktop does not support colour depth %d; falling back to %d", + g_server_depth, depth); g_server_depth = depth; } if (g_width != width || g_height != height) { - warning("Remote desktop changed from %dx%d to %dx%d.\n", g_width, g_height, - width, height); + logger(Protocol, Debug, + "rdp_process_bitmap_caps(), remote desktop changed from %dx%d to %dx%d.\n", + g_width, g_height, width, height); g_width = width; g_height = height; ui_resize_window(); @@ -1027,7 +1028,8 @@ process_demand_active(STREAM s) in_uint16_le(s, len_combined_caps); in_uint8s(s, len_src_descriptor); - DEBUG(("DEMAND_ACTIVE(id=0x%x)\n", g_rdp_shareid)); + logger(Protocol, Debug, "process_demand_active(), shareid=0x%x", g_rdp_shareid); + rdp_process_server_caps(s, len_combined_caps); rdp_send_confirm_active(); @@ -1076,7 +1078,8 @@ process_colour_pointer_common(STREAM s, int bpp) in_uint8p(s, mask, masklen); if ((width != 32) || (height != 32)) { - warning("process_colour_pointer_common: " "width %d height %d\n", width, height); + logger(Protocol, Warning, "process_colour_pointer_common(), width %d height %d", + width, height); } /* keep hotspot within cursor bounding box */ @@ -1128,7 +1131,9 @@ process_system_pointer_pdu(STREAM s) break; default: - unimpl("System pointer message 0x%x\n", system_pointer_type); + logger(Protocol, Warning, + "process_system_pointer_pdu(), unhandled pointer type 0x%x", + system_pointer_type); } } @@ -1168,7 +1173,8 @@ process_pointer_pdu(STREAM s) break; default: - unimpl("Pointer message 0x%x\n", message_type); + logger(Protocol, Warning, + "process_pointer_pdu(), unhandled message type 0x%x", message_type); } } @@ -1200,8 +1206,9 @@ process_bitmap_updates(STREAM s) cx = right - left + 1; cy = bottom - top + 1; - DEBUG(("BITMAP_UPDATE(l=%d,t=%d,r=%d,b=%d,w=%d,h=%d,Bpp=%d,cmp=%d)\n", - left, top, right, bottom, width, height, Bpp, compress)); + logger(Graphics, Debug, + "process_bitmap_updates(), [%d,%d,%d,%d], [%d,%d], bpp=%d, compression=%d", + left, top, right, bottom, width, height, Bpp, compress); if (!compress) { @@ -1236,7 +1243,8 @@ process_bitmap_updates(STREAM s) } else { - DEBUG_RDP5(("Failed to decompress data\n")); + logger(Graphics, Warning, + "process_bitmap_updates(), failed to decompress bitmap"); } xfree(bmpdata); @@ -1258,7 +1266,7 @@ process_palette(STREAM s) map.colours = (COLOURENTRY *) xmalloc(sizeof(COLOURENTRY) * map.ncolours); - DEBUG(("PALETTE(c=%d)\n", map.ncolours)); + logger(Graphics, Debug, "process_palette(), colour count %d", map.ncolours); for (i = 0; i < map.ncolours; i++) { @@ -1304,7 +1312,8 @@ process_update_pdu(STREAM s) break; default: - unimpl("update %d\n", update_type); + logger(Protocol, Warning, "process_update_pdu(), unhandled update type %d", + update_type); } ui_end_update(); } @@ -1334,14 +1343,16 @@ process_pdu_logon(STREAM s) in_uint32_le(s, len); if (len != 28) { - warning("Invalid length in Auto-Reconnect packet\n"); + logger(Protocol, Error, + "process_pdu_logon(), invalid length in Auto-Reconnect packet"); return; } in_uint32_le(s, version); if (version != 1) { - warning("Unsupported version of Auto-Reconnect packet\n"); + logger(Protocol, Error, + "process_pdu_logon(), unsupported version of Auto-Reconnect packet"); return; } @@ -1349,7 +1360,9 @@ process_pdu_logon(STREAM s) in_uint8a(s, g_reconnect_random, 16); g_has_reconnect_random = True; g_reconnect_random_ts = time(NULL); - DEBUG(("Saving auto-reconnect cookie, id=%u\n", g_reconnect_logonid)); + logger(Protocol, Debug, + "process_pdu_logon(), saving Auto-Reconnect cookie, id=%u", + g_reconnect_logonid); } } } @@ -1361,7 +1374,7 @@ process_disconnect_pdu(STREAM s, uint32 * ext_disc_reason) { in_uint32_le(s, *ext_disc_reason); - DEBUG(("Received disconnect PDU\n")); + logger(Protocol, Debug, "process_disconnect_pdu(), reason = %d", ext_disc_reason); } /* Process data PDU */ @@ -1387,9 +1400,11 @@ process_data_pdu(STREAM s, uint32 * ext_disc_reason) if (ctype & RDP_MPPC_COMPRESSED) { if (len > RDP_MPPC_DICT_SIZE) - error("error decompressed packet size exceeds max\n"); + logger(Protocol, Error, + "process_data_pdu(), error decompressed packet size exceeds max"); if (mppc_expand(s->p, clen, ctype, &roff, &rlen) == -1) - error("error while decompressing packet\n"); + logger(Protocol, Error, + "process_data_pdu(), error while decompressing packet"); /* len -= 18; */ @@ -1413,11 +1428,11 @@ process_data_pdu(STREAM s, uint32 * ext_disc_reason) break; case RDP_DATA_PDU_CONTROL: - DEBUG(("Received Control PDU\n")); + logger(Protocol, Debug, "process_data_pdu(), received Control PDU"); break; case RDP_DATA_PDU_SYNCHRONISE: - DEBUG(("Received Sync PDU\n")); + logger(Protocol, Debug, "process_data_pdu(), received Sync PDU"); break; case RDP_DATA_PDU_POINTER: @@ -1429,7 +1444,7 @@ process_data_pdu(STREAM s, uint32 * ext_disc_reason) break; case RDP_DATA_PDU_LOGON: - DEBUG(("Received Logon PDU\n")); + logger(Protocol, Debug, "process_data_pdu(), received Logon PDU"); /* User logged on */ process_pdu_logon(s); break; @@ -1445,11 +1460,13 @@ process_data_pdu(STREAM s, uint32 * ext_disc_reason) break; case RDP_DATA_PDU_AUTORECONNECT_STATUS: - warning("Automatic reconnect using cookie, failed.\n"); + logger(Protocol, Warning, + "process_data_pdu(), automatic reconnect using cookie, failed"); break; default: - unimpl("data PDU %d\n", data_pdu_type); + logger(Protocol, Warning, "process_data_pdu(), unhandled data PDU type %d", + data_pdu_type); } return False; } @@ -1488,7 +1505,7 @@ process_redirect_pdu(STREAM s, RD_BOOL enhanced_redirect /*, uint32 * ext_disc_r /* read identifier */ in_uint16_le(s, redirect_identifier); if (redirect_identifier != 0x0400) - error("Protocol error in server redirection, unexpected data."); + logger(Protocol, Error, "unexpected data in server redirection packet"); /* FIXME: skip total length */ in_uint8s(s, 2); @@ -1562,12 +1579,14 @@ process_redirect_pdu(STREAM s, RD_BOOL enhanced_redirect /*, uint32 * ext_disc_r if (g_redirect_flags & PDU_REDIRECT_DONT_STORE_USERNAME) { - warning("PDU_REDIRECT_DONT_STORE_USERNAME set\n"); + logger(Protocol, Warning, + "process_redirect_pdu(), unhandled PDU_REDIRECT_DONT_STORE_USERNAME set"); } if (g_redirect_flags & PDU_REDIRECT_USE_SMARTCARD) { - warning("PDU_REDIRECT_USE_SMARTCARD set\n"); + logger(Protocol, Warning, + "process_redirect_pdu(), unhandled PDU_REDIRECT_USE_SMARTCARD set"); } if (g_redirect_flags & PDU_REDIRECT_INFORMATIONAL) @@ -1594,12 +1613,14 @@ process_redirect_pdu(STREAM s, RD_BOOL enhanced_redirect /*, uint32 * ext_disc_r if (g_redirect_flags & PDU_REDIRECT_HAS_TARGET_NETBIOS) { - warning("PDU_REDIRECT_HAS_TARGET_NETBIOS set\n"); + logger(Protocol, Warning, + "process_redirect_pdu(), unhandled PDU_REDIRECT_HAS_TARGET_NETBIOS set"); } if (g_redirect_flags & PDU_REDIRECT_HAS_TARGET_IP_ARRAY) { - warning("PDU_REDIRECT_HAS_TARGET_IP_ARRAY set\n"); + logger(Protocol, Warning, + "process_redirect_pdu(), unhandled PDU_REDIRECT_HAS_TARGET_IP_ARRAY set"); } return True; @@ -1638,7 +1659,8 @@ rdp_loop(RD_BOOL * deactivated, uint32 * ext_disc_reason) *deactivated = False; break; case RDP_PDU_DEACTIVATE: - DEBUG(("RDP_PDU_DEACTIVATE\n")); + logger(Protocol, Debug, + "rdp_loop(), RDP_PDU_DEACTIVATE packet received"); *deactivated = True; break; case RDP_PDU_REDIRECT: @@ -1658,7 +1680,8 @@ rdp_loop(RD_BOOL * deactivated, uint32 * ext_disc_reason) case 0: break; default: - unimpl("PDU %d\n", type); + logger(Protocol, Warning, + "rdp_loop(), unhandled PDU type %d received", type); } cont = g_next_packet < s->end; } diff --git a/rdp5.c b/rdp5.c index 4173c22..f11f749 100644 --- a/rdp5.c +++ b/rdp5.c @@ -35,11 +35,6 @@ rdp5_process(STREAM s) struct stream *ns = &(g_mppc_dict.ns); struct stream *ts; -#if 0 - printf("RDP5 data:\n"); - hexdump(s->p, s->end - s->p); -#endif - ui_begin_update(); while (s->p < s->end) { @@ -60,7 +55,8 @@ rdp5_process(STREAM s) if (ctype & RDP_MPPC_COMPRESSED) { if (mppc_expand(s->p, length, ctype, &roff, &rlen) == -1) - error("error while decompressing packet\n"); + logger(Protocol, Error, + "rdp5_process(), error while decompressing packet"); /* allocate memory and copy the uncompressed data into the temporary stream */ ns->data = (uint8 *) xrealloc(ns->data, rlen); @@ -114,7 +110,8 @@ rdp5_process(STREAM s) process_new_pointer_pdu(ts); break; default: - unimpl("RDP5 opcode %d\n", type); + logger(Protocol, Warning, "rdp5_process(), unhandled opcode %d", + type); } s->p = next; diff --git a/rdpdr.c b/rdpdr.c index 92f6078..78b764c 100644 --- a/rdpdr.c +++ b/rdpdr.c @@ -2,7 +2,7 @@ rdesktop: A Remote Desktop Protocol client. Copyright (C) Matthew Chapman 1999-2008 Copyright 2004-2011 Peter Astrand for Cendio AB - Copyright 2010-2014 Henrik Andersson for Cendio AB + Copyright 2010-2017 Henrik Andersson for Cendio AB Copyright 2017 Karl Mikaelsson for Cendio AB This program is free software: you can redistribute it and/or modify @@ -329,11 +329,10 @@ rdpdr_send_completion(uint32 device, uint32 id, uint32 status, uint32 result, ui out_uint32_le(s, result); out_uint8p(s, buffer, length); s_mark_end(s); - /* JIF */ -#ifdef WITH_DEBUG_RDP5 - printf("--> rdpdr_send_completion\n"); + + logger(Protocol, Debug, "rdpdr_send_completion()"); /* hexdump(s->channel_hdr + 8, s->end - s->channel_hdr - 8); */ -#endif + channel_send(s, rdpdr_channel); #ifdef WITH_SCARD scard_unlock(SCARD_LOCK_RDPDR); @@ -383,8 +382,9 @@ rdpdr_process_irp(STREAM s) if (device >= RDPDR_MAX_DEVICES) { - error("invalid irp device 0x%lx file 0x%lx id 0x%lx major 0x%lx minor 0x%lx\n", - device, file, id, major, minor); + logger(Protocol, Error, + "rdpdr_process_irp(), invalid irp device=0x%lx, file=0x%lx, id=0x%lx, major=0x%lx, minor=0x%lx", + device, file, id, major, minor); xfree(buffer); return; } @@ -421,8 +421,9 @@ rdpdr_process_irp(STREAM s) break; #endif default: - - error("IRP for bad device %ld\n", device); + logger(Protocol, Error, + "rdpdr_process_irp(), received IRP for unknown device type %ld", + device); xfree(buffer); return; } @@ -480,9 +481,11 @@ rdpdr_process_irp(STREAM s) in_uint32_le(s, length); in_uint32_le(s, offset); -#if WITH_DEBUG_RDP5 - DEBUG(("RDPDR IRP Read (length: %d, offset: %d)\n", length, offset)); -#endif + + logger(Protocol, Debug, + "rdpdr_process_irp(), IRP Read length=%d, offset=%d", length, + offset); + if (!rdpdr_handle_ok(device, file)) { status = RD_STATUS_INVALID_HANDLE; @@ -533,9 +536,9 @@ rdpdr_process_irp(STREAM s) in_uint32_le(s, length); in_uint32_le(s, offset); in_uint8s(s, 0x18); -#if WITH_DEBUG_RDP5 - DEBUG(("RDPDR IRP Write (length: %d)\n", result)); -#endif + + logger(Protocol, Debug, "rdpdr_process_irp(), IRP Write length=%d", result); + if (!rdpdr_handle_ok(device, file)) { status = RD_STATUS_INVALID_HANDLE; @@ -669,7 +672,9 @@ rdpdr_process_irp(STREAM s) status = RD_STATUS_INVALID_PARAMETER; /* JIF */ - unimpl("IRP major=0x%x minor=0x%x\n", major, minor); + logger(Protocol, Warning, + "rdpdr_process_irp(), unhandled minor opcode, major=0x%x, minor=0x%x", + major, minor); } break; @@ -738,7 +743,9 @@ rdpdr_process_irp(STREAM s) break; default: - unimpl("IRP major=0x%x minor=0x%x\n", major, minor); + logger(Protocol, Warning, + "rdpdr_process_irp(), unhandled major opcode, major=0x%x, minor=0x%x", + major, minor); break; } @@ -804,10 +811,8 @@ rdpdr_process(STREAM s) uint16 component; uint16 pakid; -#if WITH_DEBUG_RDP5 - printf("--- rdpdr_process ---\n"); - hexdump(s->p, s->end - s->p); -#endif + logger(Protocol, Debug, "rdpdr_process()"); + /* hexdump(s->p, s->end - s->p); */ in_uint16(s, component); in_uint16(s, pakid); @@ -842,9 +847,8 @@ rdpdr_process(STREAM s) case PAKID_CORE_DEVICE_REPLY: in_uint32(s, handle); -#if WITH_DEBUG_RDP5 - DEBUG(("RDPDR: Server connected to resource %d\n", handle)); -#endif + logger(Protocol, Debug, + "rdpdr_process(), server connected to resource %d", handle); break; case PAKID_CORE_SERVER_CAPABILITY: @@ -852,7 +856,9 @@ rdpdr_process(STREAM s) break; default: - unimpl("RDPDR pakid 0x%x of component 0x%x\n", pakid, component); + logger(Protocol, Debug, + "rdpdr_process(), pakid 0x%x of component 0x%x", pakid, + component); break; } @@ -863,7 +869,7 @@ rdpdr_process(STREAM s) printercache_process(s); } else - unimpl("RDPDR component 0x%x\n", component); + logger(Protocol, Warning, "rdpdr_process(), unhandled component 0x%x", component); } RD_BOOL @@ -1063,17 +1069,19 @@ _rdpdr_check_fds(fd_set * rfds, fd_set * wfds, RD_BOOL timed_out) iorq->partial_len += result; iorq->offset += result; } -#if WITH_DEBUG_RDP5 - DEBUG(("RDPDR: %d bytes of data read\n", result)); -#endif + + logger(Protocol, Debug, + "_rdpdr_check_fds(), %d bytes of data read", + result); + /* only delete link if all data has been transfered */ /* or if result was 0 and status success - EOF */ if ((iorq->partial_len == iorq->length) || (result == 0)) { -#if WITH_DEBUG_RDP5 - DEBUG(("RDPDR: AIO total %u bytes read of %u\n", iorq->partial_len, iorq->length)); -#endif + logger(Protocol, Debug, + "_rdpdr_check_fds(), AIO total %u bytes read of %u", + iorq->partial_len, iorq->length); rdpdr_send_completion(iorq->device, iorq->id, status, iorq->partial_len, @@ -1106,18 +1114,18 @@ _rdpdr_check_fds(fd_set * rfds, fd_set * wfds, RD_BOOL timed_out) iorq->offset += result; } -#if WITH_DEBUG_RDP5 - DEBUG(("RDPDR: %d bytes of data written\n", - result)); -#endif + logger(Protocol, Debug, + "_rdpdr_check_fds(), %d bytes of data written", + result); + /* only delete link if all data has been transfered */ /* or we couldn't write */ if ((iorq->partial_len == iorq->length) || (result == 0)) { -#if WITH_DEBUG_RDP5 - DEBUG(("RDPDR: AIO total %u bytes written of %u\n", iorq->partial_len, iorq->length)); -#endif + logger(Protocol, Debug, + "_rdpdr_check_fds(), AIO total %u bytes written of %u", + iorq->partial_len, iorq->length); rdpdr_send_completion(iorq->device, iorq->id, status, iorq->partial_len, diff --git a/rdpsnd.c b/rdpsnd.c index db9681f..fce11f6 100644 --- a/rdpsnd.c +++ b/rdpsnd.c @@ -95,8 +95,8 @@ rdpsnd_send_completion(uint16 tick, uint8 packet_index) s_mark_end(s); rdpsnd_send(s); - DEBUG_SOUND(("RDPSND: -> RDPSND_COMPLETION(tick: %u, index: %u)\n", - (unsigned) tick, (unsigned) packet_index)); + logger(Sound, Debug, "rdpsnd_send_completion(), tick=%u, index=%u", + (unsigned) tick, (unsigned) packet_index); } void @@ -115,17 +115,19 @@ rdpsnd_auto_select(void) current_driver = drivers; while (current_driver != NULL) { - DEBUG(("trying %s...\n", current_driver->name)); + logger(Sound, Debug, "rdpsnd_auto_select(), trying driver '%s'", + current_driver->name); if (current_driver->wave_out_open()) { - DEBUG(("selected %s\n", current_driver->name)); + logger(Sound, Debug, "rdpsnd_auto_select(), using driver '%s'", + current_driver->name); current_driver->wave_out_close(); return True; } current_driver = current_driver->next; } - warning("no working audio-driver found\n"); + logger(Sound, Debug, "no working audio-driver found"); failed = True; current_driver = NULL; } @@ -151,12 +153,14 @@ rdpsnd_process_negotiate(STREAM in) in_uint16_le(in, version); in_uint8s(in, 1); /* padding */ - DEBUG_SOUND(("RDPSND: RDPSND_NEGOTIATE(formats: %d, pad: 0x%02x, version: %x)\n", - (int) in_format_count, (unsigned) pad, (unsigned) version)); + logger(Sound, Debug, + "rdpsnd_process_negotiate(), formats = %d, pad = 0x%02x, version = 0x%x", + (int) in_format_count, (unsigned) pad, (unsigned) version); if (rdpsnd_negotiated) { - error("RDPSND: Extra RDPSND_NEGOTIATE in the middle of a session\n"); + logger(Sound, Error, + "rdpsnd_process_negotiate(), extra RDPSND_NEGOTIATE in the middle of a session"); /* Do a complete reset of the sound state */ rdpsnd_reset_state(); } @@ -189,8 +193,9 @@ rdpsnd_process_negotiate(STREAM in) discardcnt = 0; if (format->cbSize > MAX_CBSIZE) { - fprintf(stderr, "cbSize too large for buffer: %d\n", - format->cbSize); + logger(Sound, Debug, + "rdpsnd_process_negotiate(), cbSize too large for buffer: %d", + format->cbSize); readcnt = MAX_CBSIZE; discardcnt = format->cbSize - MAX_CBSIZE; } @@ -241,7 +246,8 @@ rdpsnd_process_negotiate(STREAM in) s_mark_end(out); - DEBUG_SOUND(("RDPSND: -> RDPSND_NEGOTIATE(formats: %d)\n", (int) format_count)); + logger(Sound, Debug, "rdpsnd_process_negotiate(), %d formats available", + (int) format_count); rdpsnd_send(out); @@ -256,15 +262,13 @@ rdpsnd_process_ping(STREAM in) in_uint16_le(in, tick); - DEBUG_SOUND(("RDPSND: RDPSND_PING(tick: 0x%04x)\n", (unsigned) tick)); + logger(Sound, Debug, "rdpsmd_process_ping(), tick = 0x%04x", (unsigned) tick); out = rdpsnd_init_packet(RDPSND_PING | 0x2300, 4); out_uint16_le(out, tick); out_uint16_le(out, 0); s_mark_end(out); rdpsnd_send(out); - - DEBUG_SOUND(("RDPSND: -> (tick: 0x%04x)\n", (unsigned) tick)); } static void @@ -281,11 +285,15 @@ rdpsnd_process_packet(uint8 opcode, STREAM s) in_uint16_le(s, format); in_uint8(s, packet_index); in_uint8s(s, 3); - DEBUG_SOUND(("RDPSND: RDPSND_WRITE(tick: %u, format: %u, index: %u, data: %u bytes)\n", (unsigned) tick, (unsigned) format, (unsigned) packet_index, (unsigned) s->size - 8)); + logger(Sound, Debug, + "rdpsnd_process_packet(), RDPSND_WRITE(tick: %u, format: %u, index: %u, data: %u bytes)\n", + (unsigned) tick, (unsigned) format, (unsigned) packet_index, + (unsigned) s->size - 8); if (format >= MAX_FORMATS) { - error("RDPSND: Invalid format index\n"); + logger(Sound, Error, + "rdpsnd_process_packet(), invalid format index"); break; } @@ -323,7 +331,7 @@ rdpsnd_process_packet(uint8 opcode, STREAM s) return; break; case RDPSND_CLOSE: - DEBUG_SOUND(("RDPSND: RDPSND_CLOSE()\n")); + logger(Sound, Debug, "rdpsnd_process_packet(), RDPSND_CLOSE()"); if (device_open) current_driver->wave_out_close(); device_open = False; @@ -337,12 +345,16 @@ rdpsnd_process_packet(uint8 opcode, STREAM s) case RDPSND_SET_VOLUME: in_uint16_le(s, vol_left); in_uint16_le(s, vol_right); - DEBUG_SOUND(("RDPSND: RDPSND_VOLUME(left: 0x%04x (%u %%), right: 0x%04x (%u %%))\n", (unsigned) vol_left, (unsigned) vol_left / 655, (unsigned) vol_right, (unsigned) vol_right / 655)); + logger(Sound, Debug, + "rdpsnd_process_packet(), RDPSND_VOLUME(left: 0x%04x (%u %%), right: 0x%04x (%u %%))\n", + (unsigned) vol_left, (unsigned) vol_left / 655, (unsigned) vol_right, + (unsigned) vol_right / 655); if (device_open) current_driver->wave_out_volume(vol_left, vol_right); break; default: - unimpl("RDPSND packet type %x\n", opcode); + logger(Sound, Warning, "rdpsnd_process_packet(), Unhandled opcode 0x%x", + opcode); break; } } @@ -359,15 +371,16 @@ rdpsnd_process(STREAM s) { if ((s->end - s->p) < 4) { - error("RDPSND: Split at packet header. Things will go south from here...\n"); + logger(Sound, Error, + "rdpsnd_process(), split at packet header, things will go south from here..."); return; } in_uint8(s, packet_opcode); in_uint8s(s, 1); /* Padding */ in_uint16_le(s, len); - DEBUG_SOUND(("RDPSND: == Opcode %x Length: %d ==\n", - (int) packet_opcode, (int) len)); + logger(Sound, Error, "rdpsnd_process(), Opcode = 0x%x Length= %d", + (int) packet_opcode, (int) len); packet.p = packet.data; packet.end = packet.data + len; @@ -384,8 +397,9 @@ rdpsnd_process(STREAM s) len = MIN(len, 12 - (packet.p - packet.data)); else if ((packet.p - packet.data) == 12) { - DEBUG_SOUND(("RDPSND: Eating 4 bytes of %d bytes...\n", - len)); + logger(Sound, Debug, + "rdpsnd_process(), eating 4 bytes of %d bytes...\n", + len); in_uint8s(s, 4); len -= 4; } @@ -408,9 +422,7 @@ rdpsnd_process(STREAM s) static RD_BOOL rdpsnddbg_line_handler(const char *line, void *data) { -#ifdef WITH_DEBUG_SOUND - fprintf(stderr, "SNDDBG: %s\n", line); -#endif + logger(Sound, Debug, "rdpsnddbg_line_handler(), \"%s\"", line); return True; } @@ -489,7 +501,8 @@ rdpsnd_init(char *optarg) if ((rdpsnd_channel == NULL) || (rdpsnddbg_channel == NULL)) { - error("channel_register\n"); + logger(Sound, Error, + "rdpsnd_init(), failed to register rdpsnd / snddbg virtual channels"); return False; } @@ -522,7 +535,7 @@ rdpsnd_init(char *optarg) { if (!strcmp(pos->name, driver)) { - DEBUG(("selected %s\n", pos->name)); + logger(Sound, Debug, "rdpsnd_init(), using driver '%s'", pos->name); current_driver = pos; return True; } @@ -596,7 +609,7 @@ rdpsnd_queue_write(STREAM s, uint16 tick, uint8 index) if (next_hi == queue_pending) { - error("No space to queue audio packet\n"); + logger(Sound, Error, "rdpsnd_queue_write(), no space to queue audio packet"); return; } diff --git a/rdpsnd_alsa.c b/rdpsnd_alsa.c index ef20a8c..443d169 100644 --- a/rdpsnd_alsa.c +++ b/rdpsnd_alsa.c @@ -176,19 +176,22 @@ alsa_set_format(snd_pcm_t * pcm, RD_WAVEFORMATEX * pwfx) if ((err = snd_pcm_hw_params_malloc(&hwparams)) < 0) { - error("snd_pcm_hw_params_malloc: %s\n", snd_strerror(err)); + logger(Sound, Error, "alsa_set_format(), snd_pcm_hw_params_malloc() failed: %s", + snd_strerror(err)); return False; } if ((err = snd_pcm_hw_params_any(pcm, hwparams)) < 0) { - error("snd_pcm_hw_params_any: %s\n", snd_strerror(err)); + logger(Sound, Error, "alsa_set_format(), snd_pcm_hw_params_any() failed: %s", + snd_strerror(err)); return False; } if ((err = snd_pcm_hw_params_set_access(pcm, hwparams, SND_PCM_ACCESS_RW_INTERLEAVED)) < 0) { - error("snd_pcm_hw_params_set_access: %s\n", snd_strerror(err)); + logger(Sound, Error, "alsa_set_format(), snd_pcm_hw_params_set_access() failed: %s", + snd_strerror(err)); return False; } @@ -196,7 +199,9 @@ alsa_set_format(snd_pcm_t * pcm, RD_WAVEFORMATEX * pwfx) { if ((err = snd_pcm_hw_params_set_format(pcm, hwparams, SND_PCM_FORMAT_S16_LE)) < 0) { - error("snd_pcm_hw_params_set_format: %s\n", snd_strerror(err)); + logger(Sound, Error, + "alsa_set_format(), snd_pcm_hw_params_set_format() failed: %s", + snd_strerror(err)); return False; } } @@ -204,7 +209,9 @@ alsa_set_format(snd_pcm_t * pcm, RD_WAVEFORMATEX * pwfx) { if ((err = snd_pcm_hw_params_set_format(pcm, hwparams, SND_PCM_FORMAT_S8)) < 0) { - error("snd_pcm_hw_params_set_format: %s\n", snd_strerror(err)); + logger(Sound, Error, + "alsa_set_format(), snd_pcm_hw_params_set_format() failed: %s", + snd_strerror(err)); return False; } } @@ -212,7 +219,9 @@ alsa_set_format(snd_pcm_t * pcm, RD_WAVEFORMATEX * pwfx) #if 0 if ((err = snd_pcm_hw_params_set_rate_resample(pcm, hwparams, 1)) < 0) { - error("snd_pcm_hw_params_set_rate_resample: %s\n", snd_strerror(err)); + logger(Sound, Error, + "alsa_set_format(), snd_pcm_hw_params_set_rate_resample() failed: %s", + snd_strerror(err)); return False; } #endif @@ -220,14 +229,18 @@ alsa_set_format(snd_pcm_t * pcm, RD_WAVEFORMATEX * pwfx) rate = pwfx->nSamplesPerSec; if ((err = snd_pcm_hw_params_set_rate_near(pcm, hwparams, &rate, 0)) < 0) { - error("snd_pcm_hw_params_set_rate_near: %s\n", snd_strerror(err)); + logger(Sound, Error, + "alsa_set_format(), snd_pcm_hw_params_set_rate_near() failed: %s", + snd_strerror(err)); return False; } audiochannels = pwfx->nChannels; if ((err = snd_pcm_hw_params_set_channels(pcm, hwparams, pwfx->nChannels)) < 0) { - error("snd_pcm_hw_params_set_channels: %s\n", snd_strerror(err)); + logger(Sound, Error, + "alsa_set_format(), snd_pcm_hw_params_set_channels() failed: %s", + snd_strerror(err)); return False; } @@ -235,13 +248,16 @@ alsa_set_format(snd_pcm_t * pcm, RD_WAVEFORMATEX * pwfx) buffertime = 500000; /* microseconds */ if ((err = snd_pcm_hw_params_set_buffer_time_near(pcm, hwparams, &buffertime, 0)) < 0) { - error("snd_pcm_hw_params_set_buffer_time_near: %s\n", snd_strerror(err)); + logger(Sound, Error, + "alsa_set_format(), snd_pcm_hw_params_set_buffer_time_near() failed: %s", + snd_strerror(err)); return False; } if ((err = snd_pcm_hw_params(pcm, hwparams)) < 0) { - error("snd_pcm_hw_params: %s\n", snd_strerror(err)); + logger(Sound, Error, "alsa_set_format(), snd_pcm_hw_params(): %s", + snd_strerror(err)); return False; } @@ -249,7 +265,8 @@ alsa_set_format(snd_pcm_t * pcm, RD_WAVEFORMATEX * pwfx) if ((err = snd_pcm_prepare(pcm)) < 0) { - error("snd_pcm_prepare: %s\n", snd_strerror(err)); + logger(Sound, Error, "alsa_set_format(), snd_pcm_prepare() failed: %s\n", + snd_strerror(err)); return False; } @@ -265,7 +282,8 @@ alsa_open_out(void) if ((err = snd_pcm_open(&out_handle, pcm_name, SND_PCM_STREAM_PLAYBACK, 0)) < 0) { - error("snd_pcm_open: %s\n", snd_strerror(err)); + logger(Sound, Error, "alsa_open_out(), snd_pcm_open() failed: %s", + snd_strerror(err)); return False; } @@ -297,13 +315,17 @@ alsa_format_supported(RD_WAVEFORMATEX * pwfx) if ((err = snd_pcm_hw_params_malloc(&hwparams)) < 0) { - error("snd_pcm_hw_params_malloc: %s\n", snd_strerror(err)); + logger(Sound, Error, + "alsa_format_supported(), snd_pcm_hw_params_malloc() failed: %s", + snd_strerror(err)); return False; } if ((err = snd_pcm_hw_params_any(pcm_handle, hwparams)) < 0) { - error("snd_pcm_hw_params_malloc: %s\n", snd_strerror(err)); + logger(Sound, Error, + "alsa_format_supported(), snd_pcm_hw_params_any() failed: %s\n", + snd_strerror(err)); return False; } snd_pcm_hw_params_free(hwparams); @@ -365,7 +387,6 @@ alsa_play(void) len = (out->end - out->p) / (samplewidth_out * audiochannels_out); if ((len = snd_pcm_writei(out_handle, out->p, ((MAX_FRAMES < len) ? MAX_FRAMES : len))) < 0) { - printf("Fooo!\n"); snd_pcm_prepare(out_handle); len = 0; } @@ -388,9 +409,10 @@ alsa_play(void) if (abs((next_tick - packet->tick) - duration) > 20) { - DEBUG(("duration: %d, calc: %d, ", duration, next_tick - packet->tick)); - DEBUG(("last: %d, is: %d, should: %d\n", packet->tick, - (packet->tick + duration) % 65536, next_tick % 65536)); + logger(Sound, Debug, + "alsa_play(), duration=%d, calc=%d, last=%d, is=%d, should=%d", + duration, next_tick - packet->tick, packet->tick, + (packet->tick + duration) % 65536, next_tick % 65536); } if (snd_pcm_delay(out_handle, &delay_frames) < 0) @@ -412,7 +434,8 @@ alsa_open_in(void) if ((err = snd_pcm_open(&in_handle, pcm_name, SND_PCM_STREAM_CAPTURE, SND_PCM_NONBLOCK)) < 0) { - error("snd_pcm_open: %s\n", snd_strerror(err)); + logger(Sound, Error, "alsa_open_in(), snd_pcm_open() failed: %s", + snd_strerror(err)); return False; } @@ -439,7 +462,8 @@ alsa_set_format_in(RD_WAVEFORMATEX * pwfx) if ((err = snd_pcm_start(in_handle)) < 0) { - error("snd_pcm_start: %s\n", snd_strerror(err)); + logger(Sound, Error, "alsa_open_in(), snd_pcm_start() failed: %s", + snd_strerror(err)); return False; } diff --git a/rdpsnd_dsp.c b/rdpsnd_dsp.c index 0895d7e..b815a44 100644 --- a/rdpsnd_dsp.c +++ b/rdpsnd_dsp.c @@ -2,6 +2,7 @@ rdesktop: A Remote Desktop Protocol client. Sound DSP routines Copyright (C) Michael Gernoth 2006-2008 + Copyright 2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -45,7 +46,7 @@ rdpsnd_dsp_softvol_set(uint16 left, uint16 right) { softvol_left = left; softvol_right = right; - DEBUG(("rdpsnd_dsp_softvol_set: left: %u, right: %u\n", left, right)); + logger(Sound, Debug, "rdpsnd_dsp_softvol_set(), left: %u, right: %u\n", left, right); } void @@ -105,8 +106,9 @@ rdpsnd_dsp_softvol(unsigned char *buffer, unsigned int size, RD_WAVEFORMATEX * f } } - DEBUG(("using softvol with factors left: %d, right: %d (%d/%d)\n", factor_left, - factor_right, format->wBitsPerSample, format->nChannels)); + logger(Sound, Debug, + "rdpsnd_dsp_softvol(), using softvol with factors left: %d, right: %d (%d/%d)", + factor_left, factor_right, format->wBitsPerSample, format->nChannels); } void @@ -119,7 +121,7 @@ rdpsnd_dsp_swapbytes(unsigned char *buffer, unsigned int size, RD_WAVEFORMATEX * return; if (size & 0x1) - warning("badly aligned sound data"); + logger(Sound, Warning, "rdpsnd_dsp_swapbytes(), badly aligned sound data"); for (i = 0; i < (int) size; i += 2) { @@ -152,7 +154,7 @@ rdpsnd_dsp_resample_set(uint32 device_srate, uint16 device_bitspersample, uint16 if ((src_converter = src_new(SRC_CONVERTER, device_channels, &err)) == NULL) { - warning("src_new failed: %d!\n", err); + logger(Sound, Warning, "rdpsnd_dsp_resample_set(), src_new() failed with %d", err); return False; } #endif @@ -255,7 +257,8 @@ rdpsnd_dsp_resample(unsigned char **out, unsigned char *in, unsigned int size, #ifdef HAVE_LIBSAMPLERATE if (src_converter == NULL) { - warning("no samplerate converter available!\n"); + logger(Sound, Warning, + "rdpsndp_dsp_resample_set(), no samplerate converter available"); return 0; } @@ -275,7 +278,8 @@ rdpsnd_dsp_resample(unsigned char **out, unsigned char *in, unsigned int size, resample_data.end_of_input = 0; if ((err = src_process(src_converter, &resample_data)) != 0) - error("src_process: %s", src_strerror(err)); + logger(Sound, Warning, "rdpsnd_dsp_resample_set(), src_process(): '%s'", + src_strerror(err)); xfree(infloat); @@ -289,7 +293,8 @@ rdpsnd_dsp_resample(unsigned char **out, unsigned char *in, unsigned int size, /* Michaels simple linear resampler */ if (resample_to_srate < format->nSamplesPerSec) { - warning("downsampling currently not supported!\n"); + logger(Sound, Warning, + "rdpsnd_dsp_reasmple_set(), downsampling currently not supported"); return 0; } diff --git a/rdpsnd_libao.c b/rdpsnd_libao.c index 9725faf..1642b13 100644 --- a/rdpsnd_libao.c +++ b/rdpsnd_libao.c @@ -184,9 +184,11 @@ libao_play(void) if (abs((next_tick - packet->tick) - duration) > 20) { - DEBUG(("duration: %d, calc: %d, ", duration, next_tick - packet->tick)); - DEBUG(("last: %d, is: %d, should: %d\n", packet->tick, - (packet->tick + duration) % 65536, next_tick % 65536)); + logger(Sound, Debug, + "libao_play(), duration: %d, calc: %d, last: %d, is: %d, should: %d", + duration, next_tick - packet->tick, + (packet->tick + duration) % 65536, next_tick % 65536); + } delay_us = ((out->size / 4) * (1000000 / 44100)); diff --git a/rdpsnd_oss.c b/rdpsnd_oss.c index ce0ecaf..2170906 100644 --- a/rdpsnd_oss.c +++ b/rdpsnd_oss.c @@ -5,6 +5,7 @@ Copyright (C) GuoJunBo 2003 Copyright 2006-2008 Pierre Ossman for Cendio AB Copyright 2005-2011 Peter Astrand for Cendio AB + Copyright 2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -33,6 +34,7 @@ #include "rdesktop.h" #include "rdpsnd.h" #include "rdpsnd_dsp.h" + #include #include #include @@ -154,7 +156,8 @@ oss_open(int wanted) if ((ioctl(dsp_fd, SNDCTL_DSP_GETCAPS, &caps) < 0) || !(caps & DSP_CAP_DUPLEX)) { - warning("This device is not capable of full duplex operation.\n"); + logger(Sound, Warning, + "this OSS device is not capable of full duplex operation"); return False; } close(dsp_fd); @@ -173,7 +176,7 @@ oss_open(int wanted) if (dsp_fd == -1) { - perror(dsp_dev); + logger(Sound, Error, "oss_open(), open() failed: %s", strerror(errno)); return False; } @@ -282,7 +285,8 @@ oss_set_format(RD_WAVEFORMATEX * pwfx) if (ioctl(dsp_fd, SNDCTL_DSP_SETFMT, &format) == -1) { - perror("SNDCTL_DSP_SETFMT"); + logger(Sound, Error, "oss_set_format(), ioctl(SNDCTL_DSP_SETFMT) failed: %s", + strerror(errno)); oss_close(); return False; } @@ -299,7 +303,8 @@ oss_set_format(RD_WAVEFORMATEX * pwfx) if (ioctl(dsp_fd, SNDCTL_DSP_STEREO, &stereo) == -1) { - perror("SNDCTL_DSP_CHANNELS"); + logger(Sound, Error, "oss_set_format(), ioctl(SNDCTL_DSP_CHANNELS) failed: %s", + strerror(errno)); oss_close(); return False; } @@ -321,7 +326,8 @@ oss_set_format(RD_WAVEFORMATEX * pwfx) if (rdpsnd_dsp_resample_set (snd_rate, pwfx->wBitsPerSample, pwfx->nChannels) == False) { - error("rdpsnd_dsp_resample_set failed"); + logger(Sound, Error, + "oss_set_format(), rdpsnd_dsp_resample_set() failed"); oss_close(); return False; } @@ -333,7 +339,8 @@ oss_set_format(RD_WAVEFORMATEX * pwfx) if (*prates == 0) { - perror("SNDCTL_DSP_SPEED"); + logger(Sound, Error, "oss_set_format(), SNDCTL_DSP_SPEED failed: %s", + strerror(errno)); oss_close(); return False; } @@ -350,16 +357,17 @@ oss_set_format(RD_WAVEFORMATEX * pwfx) memset(&info, 0, sizeof(info)); if (ioctl(dsp_fd, SNDCTL_DSP_GETOSPACE, &info) == -1) { - perror("SNDCTL_DSP_GETOSPACE"); + logger(Sound, Error, "SNDCTL_DSP_GETOSPACE ioctl failed: %s", + strerror(errno)); oss_close(); return False; } if (info.fragments == 0 || info.fragstotal == 0 || info.fragsize == 0) { - fprintf(stderr, - "Broken OSS-driver detected: fragments: %d, fragstotal: %d, fragsize: %d\n", - info.fragments, info.fragstotal, info.fragsize); + logger(Sound, Error, + "broken OSS-driver detected: fragments: %d, fragstotal: %d, fragsize: %d\n", + info.fragments, info.fragstotal, info.fragsize); driver_broken = True; } } @@ -379,7 +387,8 @@ oss_volume(uint16 left, uint16 right) if (ioctl(dsp_fd, MIXER_WRITE(SOUND_MIXER_PCM), &volume) == -1) { - warning("hardware volume control unavailable, falling back to software volume control!\n"); + logger(Sound, Warning, + "hardware volume control unavailable, falling back to software volume control"); oss_driver.wave_out_volume = rdpsnd_dsp_softvol_set; rdpsnd_dsp_softvol_set(left, right); return; @@ -410,7 +419,7 @@ oss_play(void) if (errno != EWOULDBLOCK) { if (!dsp_broken) - perror("RDPSND: write()"); + logger(Sound, Error, "failed to write buffer: %s", strerror(errno)); dsp_broken = True; rdpsnd_queue_next(0); } @@ -471,7 +480,7 @@ oss_record(void) if (errno != EWOULDBLOCK) { if (!dsp_broken) - perror("RDPSND: read()"); + logger(Sound, Error, "failed to read samples: %s", strerror(errno)); dsp_broken = True; rdpsnd_queue_next(0); } diff --git a/rdpsnd_sgi.c b/rdpsnd_sgi.c index fa374ef..07c07fd 100644 --- a/rdpsnd_sgi.c +++ b/rdpsnd_sgi.c @@ -67,45 +67,45 @@ sgi_open(void) static int warned = 0; #if (defined(IRIX_DEBUG)) - fprintf(stderr, "sgi_open: begin\n"); + logger(Sound, Debug, "sgi_open()"); #endif if (!warned && sgi_output_device) { - warning("device-options not supported for libao-driver\n"); + logger(Sound, Warning, "sgi_open(), device-options not supported for libao-driver"); warned = 1; } if (alGetParamInfo(AL_DEFAULT_OUTPUT, AL_GAIN, &pinfo) < 0) { - fprintf(stderr, "sgi_open: alGetParamInfo failed: %s\n", - alGetErrorString(oserror())); + logger(Sound, Error, "sgi_open(), alGetParamInfo failed: %s", + alGetErrorString(oserror())); } min_volume = alFixedToDouble(pinfo.min.ll); max_volume = alFixedToDouble(pinfo.max.ll); volume_range = (max_volume - min_volume); -#if (defined(IRIX_DEBUG)) - fprintf(stderr, "sgi_open: minvol = %lf, maxvol= %lf, range = %lf.\n", - min_volume, max_volume, volume_range); -#endif + + logger(Sound, Debug, "sgi_open(), minvol = %lf, maxvol= %lf, range = %lf", + min_volume, max_volume, volume_range); + audioconfig = alNewConfig(); if (audioconfig == (ALconfig) 0) { - fprintf(stderr, "sgi_open: alNewConfig failed: %s\n", alGetErrorString(oserror())); + logger(Sound, Error, "sgi_open(), alNewConfig failed: %s", + alGetErrorString(oserror())); return False; } output_port = alOpenPort("rdpsnd", "w", 0); if (output_port == (ALport) 0) { - fprintf(stderr, "sgi_open: alOpenPort failed: %s\n", alGetErrorString(oserror())); + logger(Sound, Error, "sgi_open(), alOpenPort failed: %s", + alGetErrorString(oserror())); return False; } -#if (defined(IRIX_DEBUG)) - fprintf(stderr, "sgi_open: returning\n"); -#endif + logger(Sound, Debug, "sgi_open(), done"); return True; } @@ -113,9 +113,7 @@ void sgi_close(void) { /* Ack all remaining packets */ -#if (defined(IRIX_DEBUG)) - fprintf(stderr, "sgi_close: begin\n"); -#endif + logger(Sound, Debug, "sgi_close()"); while (!rdpsnd_queue_empty()) rdpsnd_queue_next(0); @@ -124,9 +122,8 @@ sgi_close(void) alClosePort(output_port); output_port = (ALport) 0; alFreeConfig(audioconfig); -#if (defined(IRIX_DEBUG)) - fprintf(stderr, "sgi_close: returning\n"); -#endif + + logger(Sound, Debug, "sgi_close(), done"); } RD_BOOL @@ -149,9 +146,7 @@ sgi_set_format(RD_WAVEFORMATEX * pwfx) int frameSize, channelCount; ALpv params; -#if (defined(IRIX_DEBUG)) - fprintf(stderr, "sgi_set_format: init...\n"); -#endif + logger(Sound, Debug, "sgi_set_format()"); if (pwfx->wBitsPerSample == 8) width = AL_SAMPLE_8; @@ -177,8 +172,8 @@ sgi_set_format(RD_WAVEFORMATEX * pwfx) if (output_port == (ALport) 0) { - fprintf(stderr, "sgi_set_format: alOpenPort failed: %s\n", - alGetErrorString(oserror())); + logger(Sound, Error, "sgi_set_format(), alOpenPort failed: %s", + alGetErrorString(oserror())); return False; } @@ -191,7 +186,7 @@ sgi_set_format(RD_WAVEFORMATEX * pwfx) if (frameSize == 0 || channelCount == 0) { - fprintf(stderr, "sgi_set_format: bad frameSize or channelCount\n"); + logger(Sound, Error, "sgi_set_format(), bad frameSize or channelCount"); return False; } combinedFrameSize = frameSize * channelCount; @@ -201,19 +196,18 @@ sgi_set_format(RD_WAVEFORMATEX * pwfx) if (alSetParams(resource, ¶ms, 1) < 0) { - fprintf(stderr, "wave_set_format: alSetParams failed: %s\n", - alGetErrorString(oserror())); + logger(Sound, Error, "sgi_set_format(), alSetParams failed: %s", + alGetErrorString(oserror())); return False; } if (params.sizeOut < 0) { - fprintf(stderr, "wave_set_format: invalid rate %d\n", g_snd_rate); + logger(Sound, Error, "sgi_set_format(), invalid rate %d", g_snd_rate); return False; } -#if (defined(IRIX_DEBUG)) - fprintf(stderr, "sgi_set_format: returning...\n"); -#endif + logger(Sound, Debug, "sgi_set_format(), done"); + return True; } @@ -224,10 +218,8 @@ sgi_volume(uint16 left, uint16 right) ALpv pv[1]; ALfixed gain[8]; -#if (defined(IRIX_DEBUG)) - fprintf(stderr, "sgi_volume: begin\n"); - fprintf(stderr, "left='%d', right='%d'\n", left, right); -#endif + + logger(Sound, Debug, "sgi_volume(), left=%d, right=%d", left, right); gainleft = (double) left / IRIX_MAX_VOL; gainright = (double) right / IRIX_MAX_VOL; @@ -240,14 +232,12 @@ sgi_volume(uint16 left, uint16 right) pv[0].sizeIn = 8; if (alSetParams(AL_DEFAULT_OUTPUT, pv, 1) < 0) { - fprintf(stderr, "sgi_volume: alSetParams failed: %s\n", - alGetErrorString(oserror())); + logger(Sound, Error, "sgi_volume(), alSetParams failed: %s", + alGetErrorString(oserror())); return; } -#if (defined(IRIX_DEBUG)) - fprintf(stderr, "sgi_volume: returning\n"); -#endif + logger(Sound, Debug, "sgi_volume(), done"); } void @@ -280,9 +270,7 @@ sgi_play(void) } else { -#if (defined(IRIX_DEBUG)) -/* fprintf(stderr,"Busy playing...\n"); */ -#endif +/* logger(Sound,Debug, "sgi_play(), busy playing..."); */ usleep(10); return; } diff --git a/rdpsnd_sun.c b/rdpsnd_sun.c index 4a7407f..3f78e24 100644 --- a/rdpsnd_sun.c +++ b/rdpsnd_sun.c @@ -6,6 +6,7 @@ Copyright (C) Michael Gernoth 2003-2008 Copyright 2007-2008 Pierre Ossman for Cendio AB Copyright 2008-2011 Peter Astrand for Cendio AB + Copyright 2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -162,7 +163,7 @@ sun_open(int mode) dsp_fd = open(dsp_dev, dsp_mode | O_NONBLOCK); if (dsp_fd == -1) { - perror(dsp_dev); + logger(Sound, Error, "sun_open(), open() failed: %s", strerror(errno)); return False; } } @@ -357,7 +358,8 @@ sun_set_format(RD_WAVEFORMATEX * pwfx) if (ioctl(dsp_fd, AUDIO_SETINFO, &info) == -1) { - perror("AUDIO_SETINFO"); + logger(Sound, Error, "sun_set_format(), ioctl(AUDIO_SETINFO) failed: %s", + strerror(errno)); sun_close(); return False; } @@ -397,7 +399,8 @@ sun_volume(uint16 left, uint16 right) if (ioctl(dsp_fd, AUDIO_SETINFO, &info) == -1) { - perror("AUDIO_SETINFO"); + logger(Sound, Error, "sun_set_volume(), ioctl(AUDIO_SETINFO) failed: %s", + strerror(errno)); return; } } @@ -424,7 +427,8 @@ sun_play(void) if (errno != EWOULDBLOCK) { if (!dsp_broken) - perror("RDPSND: write()"); + logger(Sound, Error, "sun_play(), write() failed: %s", + strerror(errno)); dsp_broken = True; rdpsnd_queue_next(0); } @@ -463,7 +467,7 @@ sun_record(void) if (len == -1) { if (errno != EWOULDBLOCK) - perror("read audio"); + logger(Sound, Error, "sun_record(), read() failed: %s", strerror(errno)); return; } diff --git a/scard.c b/scard.c index c2e1fb2..ac2398b 100644 --- a/scard.c +++ b/scard.c @@ -3,7 +3,7 @@ Smart Card support Copyright (C) Alexi Volkov 2006 Copyright 2010-2013 Pierre Ossman for Cendio AB - Copyright 2011-2014 Henrik Andersson for Cendio AB + Copyright 2011-2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -143,7 +143,7 @@ scard_enum_devices(uint32 * id, char *optarg) rv = SCardEstablishContext(SCARD_SCOPE_SYSTEM, NULL, NULL, &hContext); if (rv != SCARD_S_SUCCESS) { - error("scard_enum_devices: PCSC service not available\n"); + logger(SmartCard, Error, "scard_enum_devices(), PCSC service not available"); return 0; } else @@ -153,26 +153,29 @@ scard_enum_devices(uint32 * id, char *optarg) if (0 != pthread_mutex_init(&queueAccess, NULL)) { - error("scard_enum_devices: Can't initialize queue access mutex\n"); + logger(SmartCard, Error, + "scard_enum_devices(), can't initialize queue access mutex"); return 0; } if (0 != pthread_cond_init(&queueEmpty, NULL)) { - error("scard_enum_devices: Can't initialize queue control cv\n"); + logger(SmartCard, Error, "scard_enum_devices(), can't initialize queue control cv"); return 0; } if (0 != pthread_mutex_init(&hcardAccess, NULL)) { - error("scard_enum_devices: Can't initialize hcard list access mutex\n"); + logger(SmartCard, Error, + "scard_enum_devices(), can't initialize hcard list access mutex"); return 0; } if (0 != pthread_create(&queueHandler, NULL, (void *(*)(void *)) queue_handler_function, NULL)) { - error("scard_enum_devices: Can't create queue handling Thread\n"); + logger(SmartCard, Error, + "scard_enum_devices(), can't create queue handling thread"); return 0; } @@ -202,10 +205,9 @@ scard_enum_devices(uint32 * id, char *optarg) vendor = "\0"; } - printf("Static/aliased Device:\n"); - printf(" Lin name: [%s]\n", name); - printf(" Win name: [%s]\n", alias); - printf(" Vendor : [%s]\n", vendor); + logger(SmartCard, Debug, + "scard_enum_devices(), name='%s', alias='%s', vendor='%s'", + name, alias, vendor); nameMapCount++; if (nameMapList == NULL) @@ -283,7 +285,11 @@ _scard_handle_list_add(long handle) g_scard_handle_counter++; if (g_scard_handle_counter == 0 && overlap) - assert(!"broken smartcard client software, handles are not freed and there is no more handles left to allocate."); + { + logger(SmartCard, Error, + "_scard_handle_list_add(), broken smartcard client software, handles are not freed and no more handles left to allocate"); + abort(); + } if (g_scard_handle_counter == 0) overlap = g_scard_handle_counter = 1; @@ -662,7 +668,7 @@ TS_SCardEstablishContext(STREAM in, STREAM out) /* code segment */ - DEBUG_SCARD(("SCARD: SCardEstablishContext()\n")); + logger(SmartCard, Debug, "TS_SCardEstablishContext()"); rv = SCardEstablishContext(SCARD_SCOPE_SYSTEM, NULL, NULL, &myHContext); hContext = 0; @@ -675,13 +681,14 @@ TS_SCardEstablishContext(STREAM in, STREAM out) if (rv) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardEstablishContext(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success (context: 0x%08x [0x%lx])\n", hContext, - myHContext)); + logger(SmartCard, Debug, + "TS_SCardEstablishContext(), success. context: 0x%08x, [0x%lx]", hContext, + myHContext); } @@ -706,8 +713,8 @@ TS_SCardReleaseContext(STREAM in, STREAM out) in_uint32_le(in, hContext); myHContext = _scard_handle_list_get_pcsc_handle(hContext); - DEBUG_SCARD(("SCARD: SCardReleaseContext(context: 0x%08x [0x%lx])\n", (unsigned) hContext, - myHContext)); + logger(SmartCard, Debug, "TS_SCardReleaseContext(), context=0x%08x [0x%lx]", + (unsigned) hContext, myHContext); rv = SCardReleaseContext(myHContext); @@ -715,12 +722,15 @@ TS_SCardReleaseContext(STREAM in, STREAM out) if (rv) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardReleaseContext(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success\n")); + logger(SmartCard, Debug, + "TS_SCardReleaseContext(), success, context: 0x%08x, [0x%lx]", hContext, + myHContext); + } outForceAlignment(out, 8); @@ -742,8 +752,9 @@ TS_SCardIsValidContext(STREAM in, STREAM out) myHContext = _scard_handle_list_get_pcsc_handle(hContext); - DEBUG_SCARD(("SCARD: SCardIsValidContext(context: 0x%08x [0x%lx])\n", - (unsigned) hContext, myHContext)); + logger(SmartCard, Debug, "TS_SCardIsValidContext(), context: 0x%08x [0x%lx]", + (unsigned) hContext, myHContext); + /* There is no realization of SCardIsValidContext in PC/SC Lite so we call SCardListReaders */ readers = SC_xmalloc(&lcHandle, 1024); @@ -754,13 +765,15 @@ TS_SCardIsValidContext(STREAM in, STREAM out) if (rv) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardIsValidContext(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); rv = SCARD_E_INVALID_HANDLE; } else { - DEBUG_SCARD(("SCARD: -> Success\n")); + logger(SmartCard, Debug, + "TS_SCardIsValidContext(), success, context: 0x%08x, [0x%lx]", hContext, + myHContext); } outForceAlignment(out, 8); @@ -785,8 +798,10 @@ TS_SCardListReaders(STREAM in, STREAM out, RD_BOOL wide) in->p += 0x2C; in_uint32_le(in, hContext); myHContext = _scard_handle_list_get_pcsc_handle(hContext); - DEBUG_SCARD(("SCARD: SCardListReaders(context: 0x%08x [0x%lx])\n", - (unsigned) hContext, myHContext)); + + logger(SmartCard, Debug, "TS_SCardListReaders(), context: 0x%08x [0x%lx])", + (unsigned) hContext, myHContext); + plen1 = out->p; out_uint32_le(out, 0x00000000); /* Temp value for data length as 0x0 */ out_uint32_le(out, 0x01760650); @@ -805,14 +820,16 @@ TS_SCardListReaders(STREAM in, STREAM out, RD_BOOL wide) cur = readers; if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardListReaders(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { int i; PSCNameMapRec tmpMap; - DEBUG_SCARD(("SCARD: -> Success\n")); + logger(SmartCard, Debug, "TS_SCardListReaders(), success, context: 0x%08x [0x%lx]", + (unsigned) hContext, myHContext); + for (i = 0, tmpMap = nameMapList; i < nameMapCount; i++, tmpMap++) { dataLength += outString(out, tmpMap->alias, wide); @@ -826,7 +843,8 @@ TS_SCardListReaders(STREAM in, STREAM out, RD_BOOL wide) { if (!hasAlias(cur)) { - DEBUG_SCARD(("SCARD: \"%s\"\n", cur)); + logger(SmartCard, Debug, "TS_SCardListReaders(), '%s'", + cur); dataLength += outString(out, cur, wide); } cur = (void *) ((unsigned char *) cur + lenSC + 1); @@ -874,7 +892,10 @@ TS_SCardConnect(STREAM in, STREAM out, RD_BOOL wide) myHContext = _scard_handle_list_get_pcsc_handle(hContext); - DEBUG_SCARD(("SCARD: SCardConnect(context: 0x%08x [0x%lx], share: 0x%08x, proto: 0x%08x, reader: \"%s\")\n", (unsigned) hContext, myHContext, (unsigned) dwShareMode, (unsigned) dwPreferredProtocol, szReader ? szReader : "NULL")); + logger(SmartCard, Debug, + "TS_SCardConnect(), context: 0x%08x [0x%lx], share: 0x%08x, proto: 0x%08x, reader: '%s'", + (unsigned) hContext, myHContext, (unsigned) dwShareMode, + (unsigned) dwPreferredProtocol, szReader ? szReader : "NULL"); rv = SCardConnect(myHContext, szReader, (MYPCSC_DWORD) dwShareMode, (MYPCSC_DWORD) dwPreferredProtocol, &myHCard, &dwActiveProtocol); @@ -888,17 +909,19 @@ TS_SCardConnect(STREAM in, STREAM out, RD_BOOL wide) if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardConnect(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { char *szVendor = getVendor(szReader); - DEBUG_SCARD(("SCARD: -> Success (hcard: 0x%08x [0x%lx])\n", - (unsigned) hCard, myHCard)); + logger(SmartCard, Debug, "TS_SCardConnect(), success, hcard: 0x%08x [0x%lx]", + (unsigned) hCard, myHCard); + if (szVendor && (strlen(szVendor) > 0)) { - DEBUG_SCARD(("SCARD: Set Attribute ATTR_VENDOR_NAME\n")); + logger(SmartCard, Debug, + "TS_SCardConnect(), set attribute ATTR_VENDOR_NAME"); pthread_mutex_lock(&hcardAccess); PSCHCardRec hcard = xmalloc(sizeof(TSCHCardRec)); if (hcard) @@ -956,17 +979,23 @@ TS_SCardReconnect(STREAM in, STREAM out) myHCard = _scard_handle_list_get_pcsc_handle(hCard); - DEBUG_SCARD(("SCARD: SCardReconnect(context: 0x%08x, hcard: 0x%08x [%lx], share: 0x%08x, proto: 0x%08x, init: 0x%08x)\n", (unsigned) hContext, (unsigned) hCard, myHCard, (unsigned) dwShareMode, (unsigned) dwPreferredProtocol, (unsigned) dwInitialization)); + + logger(SmartCard, Debug, + "TS_SCardReconnect(), context: 0x%08x, hcard: 0x%08x [%lx], share: 0x%08x, proto: 0x%08x, init: 0x%08x", + (unsigned) hContext, (unsigned) hCard, myHCard, (unsigned) dwShareMode, + (unsigned) dwPreferredProtocol, (unsigned) dwInitialization); + rv = SCardReconnect(myHCard, (MYPCSC_DWORD) dwShareMode, (MYPCSC_DWORD) dwPreferredProtocol, (MYPCSC_DWORD) dwInitialization, &dwActiveProtocol); if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardReconnect(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success (proto: 0x%08x)\n", (unsigned) dwActiveProtocol)); + logger(SmartCard, Debug, "TS_SCardReconnect(), success, proto=0x%08x", + (unsigned) dwActiveProtocol); } out_uint32_le(out, (SERVER_DWORD) dwActiveProtocol); @@ -994,7 +1023,10 @@ TS_SCardDisconnect(STREAM in, STREAM out) myHContext = _scard_handle_list_get_pcsc_handle(hContext); myHCard = _scard_handle_list_get_pcsc_handle(hCard); - DEBUG_SCARD(("SCARD: SCardDisconnect(context: 0x%08x [0x%lx], hcard: 0x%08x [0x%lx], disposition: 0x%08x)\n", (unsigned) hContext, myHContext, (unsigned) hCard, myHCard, (unsigned) dwDisposition)); + logger(SmartCard, Debug, + "TS_SCardDisconnect(), context: 0x%08x [0x%lx], hcard: 0x%08x [0x%lx], disposition: 0x%08x", + (unsigned) hContext, myHContext, (unsigned) hCard, myHCard, + (unsigned) dwDisposition); pthread_mutex_lock(&hcardAccess); PSCHCardRec hcard = hcardFirst; @@ -1021,12 +1053,12 @@ TS_SCardDisconnect(STREAM in, STREAM out) if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardDisconnect(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success\n")); + logger(SmartCard, Debug, "TS_SCardReconnect(), success"); } outForceAlignment(out, 8); @@ -1125,7 +1157,9 @@ TS_SCardGetStatusChange(STREAM in, STREAM out, RD_BOOL wide) myHContext = _scard_handle_list_get_pcsc_handle(hContext); - DEBUG_SCARD(("SCARD: SCardGetStatusChange(context: 0x%08x [0x%lx], timeout: 0x%08x, count: %d)\n", (unsigned) hContext, myHContext, (unsigned) dwTimeout, (int) dwCount)); + logger(SmartCard, Debug, + "TS_SCardGetStatusChange(), context: 0x%08x [0x%lx], timeout: 0x%08x, count: %d", + (unsigned) hContext, myHContext, (unsigned) dwTimeout, (int) dwCount); if (dwCount > 0) { @@ -1159,10 +1193,10 @@ TS_SCardGetStatusChange(STREAM in, STREAM out, RD_BOOL wide) cur->dwCurrentState |= SCARD_STATE_IGNORE; } - DEBUG_SCARD(("SCARD: \"%s\"\n", cur->szReader ? cur->szReader : "NULL")); - DEBUG_SCARD(("SCARD: user: %p, state: 0x%08x, event: 0x%08x\n", - cur->pvUserData, (unsigned) cur->dwCurrentState, - (unsigned) cur->dwEventState)); + logger(SmartCard, Debug, + "TS_SCardGetStatusChange(), reader='%s', user=%p, state=%x%08x, event=0x%08x", + cur->szReader ? cur->szReader : "NULL", cur->pvUserData, + (unsigned) cur->dwCurrentState, (unsigned) cur->dwEventState); } } else @@ -1187,12 +1221,12 @@ TS_SCardGetStatusChange(STREAM in, STREAM out, RD_BOOL wide) if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardGetStatusChange(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success\n")); + logger(SmartCard, Debug, "TS_SCardGetStatusChange(), success"); } out_uint32_le(out, dwCount); @@ -1201,10 +1235,10 @@ TS_SCardGetStatusChange(STREAM in, STREAM out, RD_BOOL wide) for (i = 0, cur = rsArray; i < dwCount; i++, cur++) { - DEBUG_SCARD(("SCARD: \"%s\"\n", cur->szReader ? cur->szReader : "NULL")); - DEBUG_SCARD(("SCARD: user: %p, state: 0x%08x, event: 0x%08x\n", - cur->pvUserData, (unsigned) cur->dwCurrentState, - (unsigned) cur->dwEventState)); + logger(SmartCard, Debug, + "TS_SCardGetStatusChange(), reader='%s', user=%p, state=%x%08x, event=0x%08x", + cur->szReader ? cur->szReader : "NULL", cur->pvUserData, + (unsigned) cur->dwCurrentState, (unsigned) cur->dwEventState); /* Do endian swaps... */ cur->dwCurrentState = swap32(cur->dwCurrentState); @@ -1231,17 +1265,18 @@ TS_SCardCancel(STREAM in, STREAM out) myHContext = _scard_handle_list_get_pcsc_handle(hContext); - DEBUG_SCARD(("SCARD: SCardCancel(context: 0x%08x [0x%08lx])\n", (unsigned) hContext, - (unsigned long) myHContext)); + logger(SmartCard, Debug, "TS_SCardCancel(), context: 0x%08x [0x%08lx]", + (unsigned) hContext, (unsigned long) myHContext); + rv = SCardCancel(myHContext); if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardCancel(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success\n")); + logger(SmartCard, Debug, "TS_SCardCancel(), success"); } outForceAlignment(out, 8); return rv; @@ -1280,26 +1315,15 @@ TS_SCardLocateCardsByATR(STREAM in, STREAM out, RD_BOOL wide) myHContext = _scard_handle_list_get_pcsc_handle(hContext); - DEBUG_SCARD(("SCARD: SCardLocateCardsByATR(context: 0x%08x [0x%08lx], atrs: %d, readers: %d)\n", (unsigned) hContext, (unsigned long) myHContext, (int) atrMaskCount, (int) readerCount)); + logger(SmartCard, Debug, + "TS_SCardLocateCardsByATR(), context: 0x%08x [0x%08lx], atrs: %d, readers: %d", + (unsigned) hContext, (unsigned long) myHContext, (int) atrMaskCount, + (int) readerCount); for (i = 0, cur = pAtrMasks; i < atrMaskCount; i++, cur++) { cur->cbAtr = swap32(cur->cbAtr); - - DEBUG_SCARD(("SCARD: ATR: ")); - for (j = 0; j < pAtrMasks->cbAtr; j++) - { - DEBUG_SCARD(("%02x%c", - (unsigned) (unsigned char) cur->rgbAtr[j], - (j == pAtrMasks->cbAtr - 1) ? ' ' : ':'))} - DEBUG_SCARD(("\n")); - DEBUG_SCARD(("SCARD: ")); - for (j = 0; j < pAtrMasks->cbAtr; j++) - { - DEBUG_SCARD(("%02x%c", - (unsigned) (unsigned char) cur->rgbMask[j], - (j == pAtrMasks->cbAtr - 1) ? ' ' : ':'))} - DEBUG_SCARD(("\n")); + /* Fixme, we might want to log the ATR and mask here */ } for (i = 0, rsCur = (SERVER_LPSCARD_READERSTATE_A) ((unsigned char **) rsArray + 2); @@ -1321,10 +1345,11 @@ TS_SCardLocateCardsByATR(STREAM in, STREAM out, RD_BOOL wide) rsCur->cbAtr = swap32(rsCur->cbAtr); inReaderName(&lcHandle, in, (char **) &rsCur->szReader, wide); - DEBUG_SCARD(("SCARD: \"%s\"\n", rsCur->szReader ? rsCur->szReader : "NULL")); - DEBUG_SCARD(("SCARD: user: %p, state: 0x%08x, event: 0x%08x\n", - rsCur->pvUserData, (unsigned) rsCur->dwCurrentState, - (unsigned) rsCur->dwEventState)); + + logger(SmartCard, Debug, + "TS_SCardLocateCardsByATR(), reader='%s', user=%p, state=%x%08x, event=0x%08x", + rsCur->szReader ? rsCur->szReader : "NULL", rsCur->pvUserData, + (unsigned) rsCur->dwCurrentState, (unsigned) rsCur->dwEventState); } memcpy(ResArray, rsArray, readerCount * sizeof(SERVER_SCARD_READERSTATE_A)); @@ -1337,12 +1362,12 @@ TS_SCardLocateCardsByATR(STREAM in, STREAM out, RD_BOOL wide) copyReaderState_MyPCSCToServer(myRsArray, rsArray, readerCount); if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardLocateCardsByATR(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success\n")); + logger(SmartCard, Debug, "TS_SCardLocateCardsByATR(), success"); cur = pAtrMasks; for (i = 0, cur = pAtrMasks; i < atrMaskCount; i++, cur++) { @@ -1362,9 +1387,12 @@ TS_SCardLocateCardsByATR(STREAM in, STREAM out, RD_BOOL wide) { rsCur->dwEventState |= 0x00000040; /* SCARD_STATE_ATRMATCH 0x00000040 */ memcpy(ResArray + j, rsCur, sizeof(SCARD_READERSTATE)); - DEBUG_SCARD(("SCARD: \"%s\"\n", - rsCur->szReader ? rsCur->szReader : "NULL")); - DEBUG_SCARD(("SCARD: user: %p, state: 0x%08x, event: 0x%08x\n", rsCur->pvUserData, (unsigned) rsCur->dwCurrentState, (unsigned) rsCur->dwEventState)); + + logger(SmartCard, Debug, + "TS_SCardLocateCardsByATR(), reader='%s', user=%p, state=%x%08x, event=0x%08x", + rsCur->szReader ? rsCur->szReader : "NULL", + rsCur->pvUserData, (unsigned) rsCur->dwCurrentState, + (unsigned) rsCur->dwEventState); } } } @@ -1400,17 +1428,17 @@ TS_SCardBeginTransaction(STREAM in, STREAM out) in->p += 0x30; in_uint32_le(in, hCard); myHCard = _scard_handle_list_get_pcsc_handle(hCard); - DEBUG_SCARD(("SCARD: SCardBeginTransaction(hcard: 0x%08x [0x%lx])\n", - (unsigned) hCard, myHCard)); + logger(SmartCard, Debug, "TS_SCardBeginTransaction(), hcard: 0x%08x [0x%lx])", + (unsigned) hCard, myHCard); rv = SCardBeginTransaction(myHCard); if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardBeginTransaction(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success\n")); + logger(SmartCard, Debug, "TS_SCardBeginTransaction(), success"); } outForceAlignment(out, 8); return rv; @@ -1431,17 +1459,18 @@ TS_SCardEndTransaction(STREAM in, STREAM out) myHCard = _scard_handle_list_get_pcsc_handle(hCard); - DEBUG_SCARD(("SCARD: SCardEndTransaction(hcard: 0x%08x [0x%lx], disposition: 0x%08x)\n", - (unsigned) hCard, (unsigned long) myHCard, (unsigned) dwDisposition)); + logger(SmartCard, Debug, + "TS_SCardEndTransaction(), hcard: 0x%08x [0x%lx], disposition: 0x%08x)", + (unsigned) hCard, (unsigned long) myHCard, (unsigned) dwDisposition); rv = SCardEndTransaction(myHCard, (MYPCSC_DWORD) dwDisposition); if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardEndTransaction(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success\n")); + logger(SmartCard, Debug, "TS_SCardEndTransaction(), success"); } outForceAlignment(out, 8); return rv; @@ -1576,7 +1605,9 @@ TS_SCardTransmit(STREAM in, STREAM out) else pioRecvPci = NULL; - DEBUG_SCARD(("SCARD: SCardTransmit(hcard: 0x%08x [0x%08lx], send: %d bytes, recv: %d bytes)\n", (unsigned) hCard, (unsigned long) myHCard, (int) cbSendLength, (int) cbRecvLength)); + logger(SmartCard, Debug, + "TS_SCardTransmit(), 0x%08x [0x%08lx], send: %d bytes, recv: %d bytes", + (unsigned) hCard, (unsigned long) myHCard, (int) cbSendLength, (int) cbRecvLength); myCbRecvLength = cbRecvLength; myPioSendPci = SC_xmalloc(&lcHandle, @@ -1607,8 +1638,9 @@ TS_SCardTransmit(STREAM in, STREAM out) /* FIXME: handle responses with length > 448 bytes */ if (cbRecvLength > 448) { - warning("Card response limited from %d to 448 bytes!\n", cbRecvLength); - DEBUG_SCARD(("SCARD: Truncated %d to %d\n", (unsigned int) cbRecvLength, 448)); + logger(SmartCard, Warning, + "TS_SCardTransmit(), card response limit reached, %d truncated to 448 bytes", + cbRecvLength); cbRecvLength = 448; } @@ -1624,12 +1656,13 @@ TS_SCardTransmit(STREAM in, STREAM out) if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardTransmit(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success (%d bytes)\n", (int) cbRecvLength)); + logger(SmartCard, Debug, "TS_SCardTransmit(), success, %d bytes", + (int) cbRecvLength); #if 0 if ((pioRecvPci != NULL) && (mypioRecvPci->cbPciLength > 0)) { @@ -1680,7 +1713,9 @@ TS_SCardStatus(STREAM in, STREAM out, RD_BOOL wide) in_uint32_le(in, hCard); in->p += 0x04; myHCard = _scard_handle_list_get_pcsc_handle(hCard); - DEBUG_SCARD(("SCARD: SCardStatus(hcard: 0x%08x [0x%08lx], reader len: %d bytes, atr len: %d bytes)\n", (unsigned) hCard, (unsigned long) myHCard, (int) dwReaderLen, (int) dwAtrLen)); + logger(SmartCard, Debug, + "TS_SCardStatus(), hcard: 0x%08x [0x%08lx], reader len: %d bytes, atr len: %d bytes", + (unsigned) hCard, (unsigned long) myHCard, (int) dwReaderLen, (int) dwAtrLen); if (dwReaderLen <= 0 || dwReaderLen == SCARD_AUTOALLOCATE || dwReaderLen > SCARD_MAX_MEM) dwReaderLen = SCARD_MAX_MEM; @@ -1717,23 +1752,16 @@ TS_SCardStatus(STREAM in, STREAM out, RD_BOOL wide) if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardTransmit(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); return SC_returnCode(rv, &lcHandle, in, out); } else { int i; - DEBUG_SCARD(("SCARD: -> Success (state: 0x%08x, proto: 0x%08x)\n", - (unsigned) dwState, (unsigned) dwProtocol)); - DEBUG_SCARD(("SCARD: Reader: \"%s\"\n", readerName ? readerName : "NULL")); - DEBUG_SCARD(("SCARD: ATR: ")); - for (i = 0; i < dwAtrLen; i++) - { - DEBUG_SCARD(("%02x%c", atr[i], (i == dwAtrLen - 1) ? ' ' : ':')); - } - DEBUG_SCARD(("\n")); + logger(SmartCard, Debug, "TS_SCardTransmit(), success, state=0x%08x, proto=0x%08x", + (unsigned) dwState, (unsigned) dwProtocol); if (dwState & (SCARD_SPECIFIC | SCARD_NEGOTIABLE)) dwState = 0x00000006; @@ -1804,8 +1832,8 @@ TS_SCardState(STREAM in, STREAM out) in->p += 0x04; myHCard = _scard_handle_list_get_pcsc_handle(hCard); - DEBUG_SCARD(("SCARD: SCardState(hcard: 0x%08x [0x%08lx], atr len: %d bytes)\n", - (unsigned) hCard, (unsigned long) myHCard, (int) dwAtrLen)); + logger(SmartCard, Debug, "TS_SCardState(), hcard: 0x%08x [0x%08lx], atrlen: %d bytes", + (unsigned) hCard, (unsigned long) myHCard, (int) dwAtrLen); dwReaderLen = SCARD_MAX_MEM; if (dwAtrLen <= 0 || dwAtrLen == SCARD_AUTOALLOCATE || dwAtrLen > SCARD_MAX_MEM) @@ -1831,22 +1859,16 @@ TS_SCardState(STREAM in, STREAM out) if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardState(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); return SC_returnCode(rv, &lcHandle, in, out); } else { int i; - DEBUG_SCARD(("SCARD: -> Success (state: 0x%08x, proto: 0x%08x)\n", - (unsigned) dwState, (unsigned) dwProtocol)); - DEBUG_SCARD(("SCARD: ATR: ")); - for (i = 0; i < dwAtrLen; i++) - { - DEBUG_SCARD(("%02x%c", atr[i], (i == dwAtrLen - 1) ? ' ' : ':')); - } - DEBUG_SCARD(("\n")); + logger(SmartCard, Debug, "TS_SCardState(), success, state=0x%08x, proto=0x%08x", + (unsigned) dwState, (unsigned) dwProtocol); if (dwState & (SCARD_SPECIFIC | SCARD_NEGOTIABLE)) dwState = 0x00000006; @@ -1906,8 +1928,8 @@ TS_SCardListReaderGroups(STREAM in, STREAM out) myHContext = _scard_handle_list_get_pcsc_handle(hContext); - DEBUG_SCARD(("SCARD: SCardListReaderGroups(context: 0x%08x [0x%08lx], groups: %d)\n", - (unsigned) hContext, (unsigned int) myHContext, (int) dwGroups)); + logger(SmartCard, Debug, "TS_SCardListReaderGroups(), ontext: 0x%08x [0x%08lx], groups: %d", + (unsigned) hContext, (unsigned int) myHContext, (int) dwGroups); if (dwGroups <= 0 || dwGroups == SCARD_AUTOALLOCATE || dwGroups > SCARD_MAX_MEM) dwGroups = SCARD_MAX_MEM; @@ -1922,8 +1944,8 @@ TS_SCardListReaderGroups(STREAM in, STREAM out) if (rv) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardListReaderGroups(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); return SC_returnCode(rv, &lcHandle, in, out); } else @@ -1931,10 +1953,10 @@ TS_SCardListReaderGroups(STREAM in, STREAM out) int i; char *cur; - DEBUG_SCARD(("SCARD: -> Success\n")); + logger(SmartCard, Debug, "TS_SCardListReaderGroups(), success"); for (i = 0, cur = szGroups; i < dwGroups; i++, cur += strlen(cur) + 1) { - DEBUG_SCARD(("SCARD: %s\n", cur)); + logger(SmartCard, Debug, "TS_SCardListReaderGroups(), %s", cur); } } @@ -1971,9 +1993,9 @@ TS_SCardGetAttrib(STREAM in, STREAM out) in_uint32_le(in, hCard); myHCard = _scard_handle_list_get_pcsc_handle(hCard); - DEBUG_SCARD(("SCARD: SCardGetAttrib(hcard: 0x%08x [0x%08lx], attrib: 0x%08x (%d bytes))\n", - (unsigned) hCard, (unsigned long) myHCard, - (unsigned) dwAttrId, (int) dwAttrLen)); + logger(SmartCard, Debug, + "TS_SCardGetAttrib(), hcard: 0x%08x [0x%08lx], attrib: 0x%08x (%d bytes)", + (unsigned) hCard, (unsigned long) myHCard, (unsigned) dwAttrId, (int) dwAttrLen); if (dwAttrLen > MAX_BUFFER_SIZE) dwAttrLen = MAX_BUFFER_SIZE; @@ -1999,13 +2021,13 @@ TS_SCardGetAttrib(STREAM in, STREAM out) if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardGetAttrib(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); return SC_returnCode(rv, &lcHandle, in, out); } else { - DEBUG_SCARD(("SCARD: -> Success (%d bytes)\n", (int) dwAttrLen)); + logger(SmartCard, Debug, "TS_SCardGetAttrib(), %d bytes", (int) dwAttrLen); out_uint32_le(out, dwAttrLen); out_uint32_le(out, 0x00000200); @@ -2046,9 +2068,10 @@ TS_SCardSetAttrib(STREAM in, STREAM out) in_uint32_le(in, hCard); myHCard = scHandleToMyPCSC(hCard); - DEBUG_SCARD(("SCARD: SCardSetAttrib(hcard: 0x%08x [0x%08lx], attrib: 0x%08x (%d bytes))\n", - (unsigned) hCard, (unsigned long) myHCard, - (unsigned) dwAttrId, (int) dwAttrLen)); + + logger(SmartCard, Debug, + "TS_SCardSetAttrib(), hcard: 0x%08x [0x%08lx], attrib: 0x%08x (%d bytes)", + (unsigned) hCard, (unsigned long) myHCard, (unsigned) dwAttrId, (int) dwAttrLen); if (dwAttrLen > MAX_BUFFER_SIZE) dwAttrLen = MAX_BUFFER_SIZE; @@ -2062,12 +2085,12 @@ TS_SCardSetAttrib(STREAM in, STREAM out) if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardSetAttrib(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success\n")); + logger(SmartCard, Debug, "TS_SCardSetAttrib(), success"); } out_uint32_le(out, 0x00000000); @@ -2129,7 +2152,11 @@ TS_SCardControl(STREAM in, STREAM out) myHCard = _scard_handle_list_get_pcsc_handle(hCard); myHContext = _scard_handle_list_get_pcsc_handle(hContext); - DEBUG_SCARD(("SCARD: SCardControl(context: 0x%08x [0x%08lx], hcard: 0x%08x [0x%08lx], code: 0x%08x, in: %d bytes, out: %d bytes)\n", (unsigned) hContext, (unsigned long) myHContext, (unsigned) hCard, (unsigned long) myHCard, (unsigned) dwControlCode, (int) nInBufferSize, (int) nOutBufferSize)); + logger(SmartCard, Debug, + "TS_SCardControl(), context: 0x%08x [0x%08lx], hcard: 0x%08x [0x%08lx], code: 0x%08x, in: %d bytes, out: %d bytes)\n", + (unsigned) hContext, (unsigned long) myHContext, (unsigned) hCard, + (unsigned long) myHCard, (unsigned) dwControlCode, (int) nInBufferSize, + (int) nOutBufferSize); /* Is this a proper Windows smart card ioctl? */ if ((dwControlCode & 0xffff0000) == (49 << 16)) @@ -2140,7 +2167,8 @@ TS_SCardControl(STREAM in, STREAM out) } else { - warning("Bogus smart card control code 0x%08x\n", dwControlCode); + logger(SmartCard, Warning, + "TS_SCardControl(), bogus smart card control code 0x%08x", dwControlCode); } #if 0 @@ -2173,12 +2201,13 @@ TS_SCardControl(STREAM in, STREAM out) if (rv != SCARD_S_SUCCESS) { - DEBUG_SCARD(("SCARD: -> Failure: %s (0x%08x)\n", - pcsc_stringify_error(rv), (unsigned int) rv)); + logger(SmartCard, Error, "TS_SCardControl(), failed: %s (0x%08x)", + pcsc_stringify_error(rv), (unsigned int) rv); } else { - DEBUG_SCARD(("SCARD: -> Success (out: %d bytes)\n", (int) nBytesReturned)); + logger(SmartCard, Debug, "TS_SCardControl(), success, out: %d bytes", + (int) nBytesReturned); } #ifdef PCSCLITE_VERSION_NUMBER @@ -2216,7 +2245,7 @@ TS_SCardControl(STREAM in, STREAM out) static MYPCSC_DWORD TS_SCardAccessStartedEvent(STREAM in, STREAM out) { - DEBUG_SCARD(("SCARD: SCardAccessStartedEvent()\n")); + logger(SmartCard, Debug, "TS_SCardAccessStartedEvent()"); out_uint8s(out, 8); return SCARD_S_SUCCESS; } @@ -2360,7 +2389,9 @@ scard_device_control(RD_NTHANDLE handle, uint32 request, STREAM in, STREAM out) } default: { - warning("SCARD: Unknown function %d\n", (int) request); + logger(SmartCard, Warning, + "scard_device_control(), unhandled operation %d", + (int) request); Result = 0x80100014; out_uint8s(out, 256); break; @@ -2598,7 +2629,8 @@ SC_handleRequest(PSCThreadData data) Result = pthread_create(&cur->thread, NULL, (void *(*)(void *)) thread_function, cur); if (0 != Result) { - error("[THREAD CREATE ERROR 0x%.8x]\n", Result); + logger(SmartCard, Error, "SC_handleRequest(), pthread_create() failed with 0x%.8x", + Result); SC_xfree(&threadListHandle, cur); SC_destroyThreadData(data); data = NULL; diff --git a/seamless.c b/seamless.c index ef9d503..a10af6e 100644 --- a/seamless.c +++ b/seamless.c @@ -3,7 +3,7 @@ Seamless Windows support Copyright 2005-2008 Peter Astrand for Cendio AB Copyright 2007-2008 Pierre Ossman for Cendio AB - Copyright 2013-2014 Henrik Andersson for Cendio AB + Copyright 2013-2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -23,12 +23,6 @@ #include #include -#ifdef WITH_DEBUG_SEAMLESS -#define DEBUG_SEAMLESS(args) printf args; -#else -#define DEBUG_SEAMLESS(args) -#endif - extern RD_BOOL g_seamless_rdp; static VCHANNEL *seamless_channel; static unsigned int seamless_serial; @@ -70,7 +64,7 @@ seamless_process_line(const char *line, void *data) l = xstrdup(line); p = l; - DEBUG_SEAMLESS(("seamlessrdp got:%s\n", p)); + logger(Core, Debug, "seamless_process_line(), got '%s'", p); tok1 = seamless_get_token(&p); tok2 = seamless_get_token(&p); @@ -285,7 +279,7 @@ seamless_process_line(const char *line, void *data) } else if (!strcmp("DEBUG", tok1)) { - DEBUG_SEAMLESS(("SeamlessRDP:%s\n", line)); + logger(Core, Debug, "seamless_process_line(), %s", line); } else if (!strcmp("SYNCBEGIN", tok1)) { @@ -364,7 +358,7 @@ seamless_line_handler(const char *line, void *data) { if (!seamless_process_line(line, data)) { - warning("SeamlessRDP: Invalid request:%s\n", line); + logger(Core, Warning, "seamless_line_handler(), invlid request '%s'", line); } return True; } @@ -380,11 +374,6 @@ seamless_process(STREAM s) /* str_handle_lines requires null terminated strings */ buf = xmalloc(pkglen + 1); STRNCPY(buf, (char *) s->p, pkglen + 1); -#if 0 - printf("seamless recv:\n"); - hexdump(s->p, pkglen); -#endif - str_handle_lines(buf, &seamless_rest, seamless_line_handler, NULL); xfree(buf); @@ -446,12 +435,7 @@ seamless_send(const char *command, const char *format, ...) s = channel_init(seamless_channel, len); out_uint8p(s, buf, len) s_mark_end(s); - DEBUG_SEAMLESS(("seamlessrdp sending:%s", buf)); - -#if 0 - printf("seamless send:\n"); - hexdump(s->channel_hdr + 8, s->end - s->channel_hdr - 8); -#endif + logger(Core, Debug, "seamless_send(), sending '%s'", buf); channel_send(s, seamless_channel); @@ -549,7 +533,9 @@ seamless_send_persistent(RD_BOOL enable) unsigned int res; if (!g_seamless_rdp) return (unsigned int) -1; - printf("%s persistent seamless mode.\n", enable ? "Enable" : "Disable"); + + logger(Core, Debug, "seamless_send_persistent(), %s persistent seamless mode", + enable ? "enable" : "disable"); res = seamless_send("PERSISTENT", "%d", enable); return res; diff --git a/secure.c b/secure.c index 83cbd0e..c06f2f2 100644 --- a/secure.c +++ b/secure.c @@ -3,6 +3,7 @@ Protocol services - RDP encryption and licensing Copyright (C) Matthew Chapman 1999-2008 Copyright 2005-2011 Peter Astrand for Cendio AB + Copyright 2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -172,7 +173,7 @@ sec_generate_keys(uint8 * client_random, uint8 * server_random, int rc4_key_size if (rc4_key_size == 1) { - DEBUG(("40-bit encryption enabled\n")); + logger(Protocol, Debug, "sec_generate_keys(), 40-bit encryption enabled"); sec_make_40bit(g_sec_sign_key); sec_make_40bit(g_sec_decrypt_key); sec_make_40bit(g_sec_encrypt_key); @@ -180,7 +181,9 @@ sec_generate_keys(uint8 * client_random, uint8 * server_random, int rc4_key_size } else { - DEBUG(("rc_4_key_size == %d, 128-bit encryption enabled\n", rc4_key_size)); + logger(Protocol, Debug, + "sec_generate_key(), rc_4_key_size == %d, 128-bit encryption enabled", + rc4_key_size); g_rc4_key_len = 16; } @@ -346,12 +349,6 @@ sec_send_to_channel(STREAM s, uint32 flags, uint16 channel) { flags &= ~SEC_ENCRYPT; datalen = s->end - s->p - 8; - -#if WITH_DEBUG - DEBUG(("Sending encrypted packet:\n")); - hexdump(s->p + 8, datalen); -#endif - sec_sign(s->p, 8, g_sec_sign_key, g_rc4_key_len, s->p + 8, datalen); sec_encrypt(s->p + 8, datalen); } @@ -474,7 +471,7 @@ sec_out_mcs_data(STREAM s, uint32 selected_protocol) out_uint32_le(s, g_encryption ? 0x3 : 0); /* encryption supported, 128-bit supported */ out_uint32(s, 0); /* Unknown */ - DEBUG_RDP5(("g_num_channels is %d\n", g_num_channels)); + logger(Protocol, Debug, "sec_out_mcs_data(), g_num_channels is %d", g_num_channels); if (g_num_channels > 0) { out_uint16_le(s, SEC_TAG_CLI_CHANNELS); @@ -482,7 +479,8 @@ sec_out_mcs_data(STREAM s, uint32 selected_protocol) out_uint32_le(s, g_num_channels); /* number of virtual channels */ for (i = 0; i < g_num_channels; i++) { - DEBUG_RDP5(("Requesting channel %s\n", g_channels[i].name)); + logger(Protocol, Debug, "sec_out_mcs_data(), requesting channel %s", + g_channels[i].name); out_uint8a(s, g_channels[i].name, 8); out_uint32_be(s, g_channels[i].flags); } @@ -500,7 +498,8 @@ sec_parse_public_key(STREAM s, uint8 * modulus, uint8 * exponent) in_uint32_le(s, magic); if (magic != SEC_RSA_MAGIC) { - error("RSA magic 0x%x\n", magic); + logger(Protocol, Error, "sec_parse_public_key(), magic (0x%x) != SEC_RSA_MAGIC", + magic); return False; } @@ -508,7 +507,9 @@ sec_parse_public_key(STREAM s, uint8 * modulus, uint8 * exponent) modulus_len -= SEC_PADDING_SIZE; if ((modulus_len < SEC_MODULUS_SIZE) || (modulus_len > SEC_MAX_MODULUS_SIZE)) { - error("Bad server public key size (%u bits)\n", modulus_len * 8); + logger(Protocol, Error, + "sec_parse_public_key(), invalid public key size (%u bits) from server", + modulus_len * 8); return False; } @@ -564,7 +565,8 @@ sec_parse_crypt_info(STREAM s, uint32 * rc4_key_size, if (random_len != SEC_RANDOM_SIZE) { - error("random len %d, expected %d\n", random_len, SEC_RANDOM_SIZE); + logger(Protocol, Error, "sec_parse_crypt_info(), got random len %d, expected %d", + random_len, SEC_RANDOM_SIZE); return False; } @@ -578,7 +580,8 @@ sec_parse_crypt_info(STREAM s, uint32 * rc4_key_size, in_uint32_le(s, flags); /* 1 = RDP4-style, 0x80000002 = X.509 */ if (flags & 1) { - DEBUG_RDP5(("We're going for the RDP4-style encryption\n")); + logger(Protocol, Debug, + "sec_parse_crypt_info(), We're going for the RDP4-style encryption"); in_uint8s(s, 8); /* unknown */ while (s->p < end) @@ -593,7 +596,8 @@ sec_parse_crypt_info(STREAM s, uint32 * rc4_key_size, case SEC_TAG_PUBKEY: if (!sec_parse_public_key(s, modulus, exponent)) return False; - DEBUG_RDP5(("Got Public key, RDP4-style\n")); + logger(Protocol, Debug, + "sec_parse_crypt_info(), got public key"); break; @@ -603,7 +607,9 @@ sec_parse_crypt_info(STREAM s, uint32 * rc4_key_size, break; default: - unimpl("crypt tag 0x%x\n", tag); + logger(Protocol, Warning, + "sec_parse_crypt_info(), unhandled crypt tag 0x%x", + tag); } s->p = next_tag; @@ -613,11 +619,13 @@ sec_parse_crypt_info(STREAM s, uint32 * rc4_key_size, { uint32 certcount; - DEBUG_RDP5(("We're going for the RDP5-style encryption\n")); + logger(Protocol, Debug, + "sec_parse_crypt_info(), We're going for the RDP5-style encryption"); in_uint32_le(s, certcount); /* Number of certificates */ if (certcount < 2) { - error("Server didn't send enough X509 certificates\n"); + logger(Protocol, Error, + "sec_parse_crypt_info(), server didn't send enough x509 certificates"); return False; } for (; certcount > 2; certcount--) @@ -625,20 +633,14 @@ sec_parse_crypt_info(STREAM s, uint32 * rc4_key_size, uint32 ignorelen; RDSSL_CERT *ignorecert; - DEBUG_RDP5(("Ignored certs left: %d\n", certcount)); in_uint32_le(s, ignorelen); - DEBUG_RDP5(("Ignored Certificate length is %d\n", ignorelen)); ignorecert = rdssl_cert_read(s->p, ignorelen); in_uint8s(s, ignorelen); if (ignorecert == NULL) { /* XXX: error out? */ - DEBUG_RDP5(("got a bad cert: this will probably screw up the rest of the communication\n")); + logger(Protocol, Error, + "sec_parse_crypt_info(), got a bad cert: this will probably screw up the rest of the communication"); } - -#ifdef WITH_DEBUG_RDP5 - DEBUG_RDP5(("cert #%d (ignored):\n", certcount)); - rdssl_cert_print_fp(stdout, ignorecert); -#endif } /* Do da funky X.509 stuffy @@ -649,29 +651,34 @@ sec_parse_crypt_info(STREAM s, uint32 * rc4_key_size, http://www.cs.auckland.ac.nz/~pgut001/pubs/x509guide.txt */ in_uint32_le(s, cacert_len); - DEBUG_RDP5(("CA Certificate length is %d\n", cacert_len)); + logger(Protocol, Debug, + "sec_parse_crypt_info(), server CA Certificate length is %d", cacert_len); cacert = rdssl_cert_read(s->p, cacert_len); in_uint8s(s, cacert_len); if (NULL == cacert) { - error("Couldn't load CA Certificate from server\n"); + logger(Protocol, Error, + "sec_parse_crypt_info(), couldn't load CA Certificate from server"); return False; } in_uint32_le(s, cert_len); - DEBUG_RDP5(("Certificate length is %d\n", cert_len)); + logger(Protocol, Debug, "sec_parse_crypt_info(), certificate length is %d", + cert_len); server_cert = rdssl_cert_read(s->p, cert_len); in_uint8s(s, cert_len); if (NULL == server_cert) { rdssl_cert_free(cacert); - error("Couldn't load Certificate from server\n"); + logger(Protocol, Error, + "sec_parse_crypt_info(), couldn't load Certificate from server"); return False; } if (!rdssl_certs_ok(server_cert, cacert)) { rdssl_cert_free(server_cert); rdssl_cert_free(cacert); - error("Security error CA Certificate invalid\n"); + logger(Protocol, Error, + "sec_parse_crypt_info(), security error, CA Certificate invalid"); return False; } rdssl_cert_free(cacert); @@ -679,7 +686,8 @@ sec_parse_crypt_info(STREAM s, uint32 * rc4_key_size, server_public_key = rdssl_cert_to_rkey(server_cert, &g_server_public_key_len); if (NULL == server_public_key) { - DEBUG_RDP5(("Didn't parse X509 correctly\n")); + logger(Protocol, Debug, + "sec_parse_crypt_info(). failed to parse X509 correctly"); rdssl_cert_free(server_cert); return False; } @@ -687,15 +695,17 @@ sec_parse_crypt_info(STREAM s, uint32 * rc4_key_size, if ((g_server_public_key_len < SEC_MODULUS_SIZE) || (g_server_public_key_len > SEC_MAX_MODULUS_SIZE)) { - error("Bad server public key size (%u bits)\n", - g_server_public_key_len * 8); + logger(Protocol, Error, + "sec_parse_crypt_info(), bad server public key size (%u bits)", + g_server_public_key_len * 8); rdssl_rkey_free(server_public_key); return False; } if (rdssl_rkey_get_exp_mod(server_public_key, exponent, SEC_EXPONENT_SIZE, modulus, SEC_MAX_MODULUS_SIZE) != 0) { - error("Problem extracting RSA exponent, modulus"); + logger(Protocol, Error, + "sec_parse_crypt_info(), problem extracting RSA exponent, modulus"); rdssl_rkey_free(server_public_key); return False; } @@ -718,10 +728,11 @@ sec_process_crypt_info(STREAM s) memset(exponent, 0, sizeof(exponent)); if (!sec_parse_crypt_info(s, &rc4_key_size, &server_random, modulus, exponent)) { - DEBUG(("Failed to parse crypt info\n")); + logger(Protocol, Error, "sec_process_crypt_info(), failed to parse crypt info"); return; } - DEBUG(("Generating client random\n")); + + logger(Protocol, Debug, "sec_parse_crypt_info(), generating client random"); generate_random(g_client_random); sec_rsa_encrypt(g_sec_crypted_random, g_client_random, SEC_RANDOM_SIZE, g_server_public_key_len, modulus, exponent); @@ -734,7 +745,8 @@ static void sec_process_srv_info(STREAM s) { in_uint16_le(s, g_server_rdp_version); - DEBUG_RDP5(("Server RDP version is %d\n", g_server_rdp_version)); + logger(Protocol, Debug, "sec_process_srv_info(), server RDP version is %d", + g_server_rdp_version); if (1 == g_server_rdp_version) { g_rdp_version = RDP_V4; @@ -783,7 +795,7 @@ sec_process_mcs_data(STREAM s) break; default: - unimpl("response tag 0x%x\n", tag); + logger(Protocol, Warning, "Unhandled response tag 0x%x", tag); } s->p = next_tag; @@ -858,10 +870,6 @@ sec_recv(uint8 * rdpver) s->p[2] = s->p[3]; s->p[3] = swapbyte; } -#ifdef WITH_DEBUG - /* warning! this debug statement will show passwords in the clear! */ - hexdump(s->p, s->end - s->p); -#endif } } else diff --git a/serial.c b/serial.c index 7f3318e..9e9b979 100644 --- a/serial.c +++ b/serial.c @@ -17,6 +17,7 @@ along with this program. If not, see . */ #include +#include #include #include #include @@ -34,12 +35,6 @@ #include "rdesktop.h" -#ifdef WITH_DEBUG_SERIAL -#define DEBUG_SERIAL(args) printf args; -#else -#define DEBUG_SERIAL(args) -#endif - #define FILE_DEVICE_SERIAL_PORT 0x1b #define SERIAL_SET_BAUD_RATE 1 @@ -538,8 +533,10 @@ serial_enum_devices(uint32 * id, char *optarg) g_rdpdr_device[*id].local_path = xmalloc(strlen(pos2) + 1); strcpy(g_rdpdr_device[*id].local_path, pos2); - printf("SERIAL %s to %s\n", g_rdpdr_device[*id].name, + + logger(Core, Debug, "serial_enum_devices(), %s to %s", g_rdpdr_device[*id].name, g_rdpdr_device[*id].local_path); + /* set device type */ g_rdpdr_device[*id].device_type = DEVICE_TYPE_SERIAL; g_rdpdr_device[*id].pdevice_data = (void *) pser_inf; @@ -565,13 +562,15 @@ serial_create(uint32 device_id, uint32 access, uint32 share_mode, uint32 disposi if (serial_fd == -1) { - perror("open"); + logger(Core, Error, "serial_create(), open '%s' failed: %s", + g_rdpdr_device[device_id].local_path, strerror(errno)); return RD_STATUS_ACCESS_DENIED; } if (!get_termios(pser_inf, serial_fd)) { - printf("INFO: SERIAL %s access denied\n", g_rdpdr_device[device_id].name); + logger(Core, Error, "serial_create(), access denied to %s", + g_rdpdr_device[device_id].name); fflush(stdout); return RD_STATUS_ACCESS_DENIED; } @@ -580,7 +579,11 @@ serial_create(uint32 device_id, uint32 access, uint32 share_mode, uint32 disposi g_rdpdr_device[device_id].handle = serial_fd; /* some sane information */ - DEBUG_SERIAL(("INFO: SERIAL %s to %s\nINFO: speed %u baud, stop bits %u, parity %u, word length %u bits, dtr %u, rts %u\n", g_rdpdr_device[device_id].name, g_rdpdr_device[device_id].local_path, pser_inf->baud_rate, pser_inf->stop_bits, pser_inf->parity, pser_inf->word_length, pser_inf->dtr, pser_inf->rts)); + logger(Core, Debug, + "serial_create(), %s to %s, speed %u baud, stop bits %u, parity %u, word length %u bits, dtr %u, rts %u", + g_rdpdr_device[device_id].name, g_rdpdr_device[device_id].local_path, + pser_inf->baud_rate, pser_inf->stop_bits, pser_inf->parity, pser_inf->word_length, + pser_inf->dtr, pser_inf->rts); pser_inf->ptermios->c_iflag &= ~(IGNBRK | BRKINT | PARMRK | ISTRIP | INLCR | IGNCR | ICRNL | IXON); @@ -601,7 +604,8 @@ serial_create(uint32 device_id, uint32 access, uint32 share_mode, uint32 disposi /* all read and writes should be non blocking */ if (fcntl(*handle, F_SETFL, O_NONBLOCK) == -1) - perror("fcntl"); + logger(Core, Error, "serial_create(), failed to set non blocking: %s", + strerror(errno)); pser_inf->read_total_timeout_constant = 5; @@ -626,7 +630,7 @@ serial_read(RD_NTHANDLE handle, uint8 * data, uint32 length, uint32 offset, uint long timeout; SERIAL_DEVICE *pser_inf; struct termios *ptermios; -#ifdef WITH_DEBUG_SERIAL +#ifdef TIOCINQ int bytes_inqueue; #endif @@ -663,18 +667,14 @@ serial_read(RD_NTHANDLE handle, uint8 * data, uint32 length, uint32 offset, uint } tcsetattr(handle, TCSANOW, ptermios); -#if defined(WITH_DEBUG_SERIAL) && defined(TIOCINQ) +#if defined(TIOCINQ) ioctl(handle, TIOCINQ, &bytes_inqueue); - DEBUG_SERIAL(("serial_read inqueue: %d expected %d\n", bytes_inqueue, length)); + logger(Core, Debug, "serial_read(), inqueue: %d expected %d\n", bytes_inqueue, length); #endif *result = read(handle, data, length); -#ifdef WITH_DEBUG_SERIAL - DEBUG_SERIAL(("serial_read Bytes %d\n", *result)); - if (*result > 0) - hexdump(data, *result); -#endif + logger(Core, Debug, "serial_read(), %d bytes read", *result); return RD_STATUS_SUCCESS; } @@ -684,6 +684,8 @@ serial_write(RD_NTHANDLE handle, uint8 * data, uint32 length, uint32 offset, uin { SERIAL_DEVICE *pser_inf; + /* FIXME: offset is not used ? */ + pser_inf = get_serial_info(handle); *result = write(handle, data, length); @@ -691,7 +693,7 @@ serial_write(RD_NTHANDLE handle, uint8 * data, uint32 length, uint32 offset, uin if (*result > 0) pser_inf->event_txempty = *result; - DEBUG_SERIAL(("serial_write length %d, offset %d result %d\n", length, offset, *result)); + logger(Core, Debug, "serial_write(), %d bytes written", *result); return RD_STATUS_SUCCESS; } @@ -720,56 +722,56 @@ serial_device_control(RD_NTHANDLE handle, uint32 request, STREAM in, STREAM out) case SERIAL_SET_BAUD_RATE: in_uint32_le(in, pser_inf->baud_rate); set_termios(pser_inf, handle); - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_BAUD_RATE %d\n", - pser_inf->baud_rate)); + logger(Protocol, Debug, "serial_device_control(), set baud rate %d", + pser_inf->baud_rate); break; case SERIAL_GET_BAUD_RATE: out_uint32_le(out, pser_inf->baud_rate); - DEBUG_SERIAL(("serial_ioctl -> SERIAL_GET_BAUD_RATE %d\n", - pser_inf->baud_rate)); + logger(Protocol, Debug, "serial_device_control(), get baud rate %d", + pser_inf->baud_rate); break; case SERIAL_SET_QUEUE_SIZE: in_uint32_le(in, pser_inf->queue_in_size); in_uint32_le(in, pser_inf->queue_out_size); - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_QUEUE_SIZE in %d out %d\n", - pser_inf->queue_in_size, pser_inf->queue_out_size)); + logger(Protocol, Debug, + "serial_device_control(), set queue size, in=%d out=%d", + pser_inf->queue_in_size, pser_inf->queue_out_size); break; case SERIAL_SET_LINE_CONTROL: in_uint8(in, pser_inf->stop_bits); in_uint8(in, pser_inf->parity); in_uint8(in, pser_inf->word_length); set_termios(pser_inf, handle); - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_LINE_CONTROL stop %d parity %d word %d\n", pser_inf->stop_bits, pser_inf->parity, pser_inf->word_length)); + logger(Protocol, Debug, + "serial_device_control(), set line control, stop=%d, parity=%d, word=%d", + pser_inf->stop_bits, pser_inf->parity, pser_inf->word_length); break; case SERIAL_GET_LINE_CONTROL: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_GET_LINE_CONTROL\n")); + logger(Protocol, Debug, "serial_device_control(), get line control"); out_uint8(out, pser_inf->stop_bits); out_uint8(out, pser_inf->parity); out_uint8(out, pser_inf->word_length); break; case SERIAL_IMMEDIATE_CHAR: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_IMMEDIATE_CHAR\n")); + logger(Protocol, Debug, "serial_device_control(), immediate char"); in_uint8(in, immediate); serial_write(handle, &immediate, 1, 0, &result); break; case SERIAL_CONFIG_SIZE: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_CONFIG_SIZE\n")); + logger(Protocol, Debug, "serial_device_control(), config size"); out_uint32_le(out, 0); break; case SERIAL_GET_CHARS: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_GET_CHARS\n")); + logger(Protocol, Debug, "serial_device_control(), get chars"); out_uint8a(out, pser_inf->chars, 6); break; case SERIAL_SET_CHARS: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_CHARS\n")); + logger(Protocol, Debug, "serial_device_control(), set chars"); in_uint8a(in, pser_inf->chars, 6); -#ifdef WITH_DEBUG_SERIAL - hexdump(pser_inf->chars, 6); -#endif set_termios(pser_inf, handle); break; case SERIAL_GET_HANDFLOW: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_GET_HANDFLOW\n")); + logger(Protocol, Debug, "serial_device_control(), get handflow"); get_termios(pser_inf, handle); out_uint32_le(out, pser_inf->control); out_uint32_le(out, pser_inf->xonoff); /* Xon/Xoff */ @@ -781,9 +783,10 @@ serial_device_control(RD_NTHANDLE handle, uint32 request, STREAM in, STREAM out) in_uint32_le(in, pser_inf->xonoff); in_uint32_le(in, pser_inf->onlimit); in_uint32_le(in, pser_inf->offlimit); - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_HANDFLOW %x %x %x %x\n", - pser_inf->control, pser_inf->xonoff, pser_inf->onlimit, - pser_inf->onlimit)); + logger(Protocol, Debug, + "serial_device_control(), set handflow, control=%x, xonoff=%x, onlimit=%x, offlimit=%x", + pser_inf->control, pser_inf->xonoff, pser_inf->onlimit, + pser_inf->offlimit); set_termios(pser_inf, handle); break; case SERIAL_SET_TIMEOUTS: @@ -792,16 +795,18 @@ serial_device_control(RD_NTHANDLE handle, uint32 request, STREAM in, STREAM out) in_uint32(in, pser_inf->read_total_timeout_constant); in_uint32(in, pser_inf->write_total_timeout_multiplier); in_uint32(in, pser_inf->write_total_timeout_constant); - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_TIMEOUTS read timeout %d %d %d\n", - pser_inf->read_interval_timeout, - pser_inf->read_total_timeout_multiplier, - pser_inf->read_total_timeout_constant)); + logger(Protocol, Debug, + "serial_device_control(), set timeouts, timeout=%d, multiplier=%d, constant=%d", + pser_inf->read_interval_timeout, + pser_inf->read_total_timeout_multiplier, + pser_inf->read_total_timeout_constant); break; case SERIAL_GET_TIMEOUTS: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_GET_TIMEOUTS read timeout %d %d %d\n", - pser_inf->read_interval_timeout, - pser_inf->read_total_timeout_multiplier, - pser_inf->read_total_timeout_constant)); + logger(Protocol, Debug, + "serial_device_control(), get timeouts, timeout=%d, multiplier=%d, constant=%d", + pser_inf->read_interval_timeout, + pser_inf->read_total_timeout_multiplier, + pser_inf->read_total_timeout_constant); out_uint32(out, pser_inf->read_interval_timeout); out_uint32(out, pser_inf->read_total_timeout_multiplier); @@ -810,38 +815,38 @@ serial_device_control(RD_NTHANDLE handle, uint32 request, STREAM in, STREAM out) out_uint32(out, pser_inf->write_total_timeout_constant); break; case SERIAL_GET_WAIT_MASK: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_GET_WAIT_MASK %X\n", - pser_inf->wait_mask)); + logger(Protocol, Debug, "serial_device_control(), get wait mask, mask=0x%x", + pser_inf->wait_mask); out_uint32(out, pser_inf->wait_mask); break; case SERIAL_SET_WAIT_MASK: in_uint32(in, pser_inf->wait_mask); - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_WAIT_MASK %X\n", - pser_inf->wait_mask)); + logger(Protocol, Debug, "serial_device_control(), set wait mask, mask=0x%x", + pser_inf->wait_mask); break; case SERIAL_SET_DTR: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_DTR\n")); + logger(Protocol, Debug, "serial_device_control(), set dtr"); ioctl(handle, TIOCMGET, &result); result |= TIOCM_DTR; ioctl(handle, TIOCMSET, &result); pser_inf->dtr = 1; break; case SERIAL_CLR_DTR: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_CLR_DTR\n")); + logger(Protocol, Debug, "serial_device_control(), clear dtr"); ioctl(handle, TIOCMGET, &result); result &= ~TIOCM_DTR; ioctl(handle, TIOCMSET, &result); pser_inf->dtr = 0; break; case SERIAL_SET_RTS: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_RTS\n")); + logger(Protocol, Debug, "serial_device_control(), set rts"); ioctl(handle, TIOCMGET, &result); result |= TIOCM_RTS; ioctl(handle, TIOCMSET, &result); pser_inf->rts = 1; break; case SERIAL_CLR_RTS: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_CLR_RTS\n")); + logger(Protocol, Debug, "serial_device_control(), clear rts"); ioctl(handle, TIOCMGET, &result); result &= ~TIOCM_RTS; ioctl(handle, TIOCMSET, &result); @@ -864,7 +869,8 @@ serial_device_control(RD_NTHANDLE handle, uint32 request, STREAM in, STREAM out) if (result & TIOCM_RTS) modemstate |= SERIAL_MS_RTS; #endif - DEBUG_SERIAL(("serial_ioctl -> SERIAL_GET_MODEMSTATUS %X\n", modemstate)); + logger(Protocol, Debug, + "serial_device_control(), get modem status, state=0x%x", modemstate); out_uint32_le(out, modemstate); break; case SERIAL_GET_COMMSTATUS: @@ -877,8 +883,9 @@ serial_device_control(RD_NTHANDLE handle, uint32 request, STREAM in, STREAM out) #endif out_uint32_le(out, result); /* Amount in in queue */ if (result) - DEBUG_SERIAL(("serial_ioctl -> SERIAL_GET_COMMSTATUS in queue %d\n", - result)); + logger(Protocol, Debug, + "serial_device_control(), get comm status, %d bytes in input queue", + result); result = 0; #ifdef TIOCOUTQ @@ -886,14 +893,17 @@ serial_device_control(RD_NTHANDLE handle, uint32 request, STREAM in, STREAM out) #endif out_uint32_le(out, result); /* Amount in out queue */ if (result) - DEBUG_SERIAL(("serial_ioctl -> SERIAL_GET_COMMSTATUS out queue %d\n", result)); + logger(Protocol, Debug, + "serial_device_control(), get comm status, %d bytes in output queue", + result); out_uint8(out, 0); /* EofReceived */ out_uint8(out, 0); /* WaitForImmediate */ break; case SERIAL_PURGE: in_uint32(in, purge_mask); - DEBUG_SERIAL(("serial_ioctl -> SERIAL_PURGE purge_mask %X\n", purge_mask)); + logger(Protocol, Debug, "serial_device_control(), purge, mask=0x%x", + purge_mask); if ((purge_mask & SERIAL_PURGE_TXCLEAR) && (purge_mask & SERIAL_PURGE_RXCLEAR)) tcflush(handle, TCIOFLUSH); @@ -907,36 +917,38 @@ serial_device_control(RD_NTHANDLE handle, uint32 request, STREAM in, STREAM out) rdpdr_abort_io(handle, 3, RD_STATUS_CANCELLED); break; case SERIAL_WAIT_ON_MASK: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_WAIT_ON_MASK %X\n", - pser_inf->wait_mask)); + logger(Protocol, Debug, "serial_device_control(), wait on mask, mask=0x%x", + pser_inf->wait_mask); pser_inf->event_pending = 1; if (serial_get_event(handle, &result)) { - DEBUG_SERIAL(("WAIT end event = %x\n", result)); + logger(Protocol, Debug, + "serial_device_control(), wait end, event=0x%x", result); out_uint32_le(out, result); break; } return RD_STATUS_PENDING; break; case SERIAL_SET_BREAK_ON: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_BREAK_ON\n")); + logger(Protocol, Debug, "serial_device_control(), set break on"); tcsendbreak(handle, 0); break; case SERIAL_RESET_DEVICE: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_RESET_DEVICE\n")); + logger(Protocol, Debug, "serial_device_control(), reset device"); break; case SERIAL_SET_BREAK_OFF: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_BREAK_OFF\n")); + logger(Protocol, Debug, "serial_device_control(), set break off"); break; case SERIAL_SET_XOFF: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_XOFF\n")); + logger(Protocol, Debug, "serial_device_control(), set xoff"); break; case SERIAL_SET_XON: - DEBUG_SERIAL(("serial_ioctl -> SERIAL_SET_XON\n")); + logger(Protocol, Debug, "serial_device_control(), set xon"); tcflow(handle, TCION); break; default: - unimpl("SERIAL IOCTL %d\n", request); + logger(Protocol, Warning, "serial_device_control(), unhandled ioctl %d", + request); return RD_STATUS_INVALID_PARAMETER; } @@ -963,13 +975,14 @@ serial_get_event(RD_NTHANDLE handle, uint32 * result) if (bytes > 0) { - DEBUG_SERIAL(("serial_get_event Bytes %d\n", bytes)); + logger(Protocol, Debug, "serial_get_event(), %d bytes", bytes); if (bytes > pser_inf->event_rlsd) { pser_inf->event_rlsd = bytes; if (pser_inf->wait_mask & SERIAL_EV_RLSD) { - DEBUG_SERIAL(("Event -> SERIAL_EV_RLSD \n")); + logger(Protocol, Debug, + "serial_get_event(), SERIAL_EV_RLSD is set"); *result |= SERIAL_EV_RLSD; ret = True; } @@ -978,13 +991,15 @@ serial_get_event(RD_NTHANDLE handle, uint32 * result) if ((bytes > 1) && (pser_inf->wait_mask & SERIAL_EV_RXFLAG)) { - DEBUG_SERIAL(("Event -> SERIAL_EV_RXFLAG Bytes %d\n", bytes)); + logger(Protocol, Debug, + "serial_get_event(), SERIAL_EV_RXFLAG is set, %d bytes", bytes); *result |= SERIAL_EV_RXFLAG; ret = True; } if ((pser_inf->wait_mask & SERIAL_EV_RXCHAR)) { - DEBUG_SERIAL(("Event -> SERIAL_EV_RXCHAR Bytes %d\n", bytes)); + logger(Protocol, Debug, + "serial_get_event(), SERIAL_EV_RXCHAR is set, %d bytes", bytes); *result |= SERIAL_EV_RXCHAR; ret = True; } @@ -1001,8 +1016,7 @@ serial_get_event(RD_NTHANDLE handle, uint32 * result) if ((bytes == 0) && (pser_inf->event_txempty > 0) && (pser_inf->wait_mask & SERIAL_EV_TXEMPTY)) { - - DEBUG_SERIAL(("Event -> SERIAL_EV_TXEMPTY\n")); + logger(Protocol, Debug, "serial_get_event(), SERIAL_EV_TXEMPT is set"); *result |= SERIAL_EV_TXEMPTY; ret = True; } @@ -1015,8 +1029,8 @@ serial_get_event(RD_NTHANDLE handle, uint32 * result) pser_inf->event_dsr = bytes & TIOCM_DSR; if (pser_inf->wait_mask & SERIAL_EV_DSR) { - DEBUG_SERIAL(("event -> SERIAL_EV_DSR %s\n", - (bytes & TIOCM_DSR) ? "ON" : "OFF")); + logger(Protocol, Debug, "serial_get_event(), SERIAL_EV_DSR=%s", + (bytes & TIOCM_DSR) ? "ON" : "OFF"); *result |= SERIAL_EV_DSR; ret = True; } @@ -1027,8 +1041,8 @@ serial_get_event(RD_NTHANDLE handle, uint32 * result) pser_inf->event_cts = bytes & TIOCM_CTS; if (pser_inf->wait_mask & SERIAL_EV_CTS) { - DEBUG_SERIAL((" EVENT-> SERIAL_EV_CTS %s\n", - (bytes & TIOCM_CTS) ? "ON" : "OFF")); + logger(Protocol, Debug, "serial_get_event(), SERIAL_EV_CTS=%s", + (bytes & TIOCM_CTS) ? "ON" : "OFF"); *result |= SERIAL_EV_CTS; ret = True; } diff --git a/ssl.c b/ssl.c index 1cbad04..1e887ed 100644 --- a/ssl.c +++ b/ssl.c @@ -3,7 +3,7 @@ Secure sockets abstraction layer Copyright (C) Matthew Chapman 1999-2008 Copyright (C) Jay Sorg 2006-2008 - Copyright (C) Henrik Andersson 2016 + Copyright 2016-2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -155,14 +155,16 @@ rdssl_cert_to_rkey(RDSSL_CERT * cert, uint32 * key_len) key = X509_get_X509_PUBKEY(cert); if (key == NULL) { - error("Failed to get public key from certificate.\n"); + logger(Protocol, Error, + "rdssl_cert_to_key(), failed to get public key from certificate"); return NULL; } ret = X509_PUBKEY_get0_param(NULL, NULL, 0, &algor, key); if (ret != 1) { - error("Faild to get algorithm used for public key.\n"); + logger(Protocol, Error, + "rdssl_cert_to_key(), failed to get algorithm used for public key"); return NULL; } @@ -170,13 +172,15 @@ rdssl_cert_to_rkey(RDSSL_CERT * cert, uint32 * key_len) if ((nid == NID_md5WithRSAEncryption) || (nid == NID_shaWithRSAEncryption)) { - DEBUG_RDP5(("Re-setting algorithm type to RSA in server certificate\n")); + logger(Protocol, Debug, + "rdssl_cert_to_key(), re-setting algorithm type to RSA in server certificate"); X509_PUBKEY_set0_param(key, OBJ_nid2obj(NID_rsaEncryption), 0, NULL, NULL, 0); } epk = X509_get_pubkey(cert); if (NULL == epk) { - error("Failed to extract public key from certificate\n"); + logger(Protocol, Error, + "rdssl_cert_to_rkey(), failed to extract public key from certificate"); return NULL; } diff --git a/tcp.c b/tcp.c index e8c8f2d..9f2b387 100644 --- a/tcp.c +++ b/tcp.c @@ -3,7 +3,7 @@ Protocol services - TCP layer Copyright (C) Matthew Chapman 1999-2008 Copyright 2005-2011 Peter Astrand for Cendio AB - Copyright 2012-2013 Henrik Andersson for Cendio AB + Copyright 2012-2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -149,8 +149,9 @@ tcp_send(STREAM s) #ifdef WITH_SCARD scard_unlock(SCARD_LOCK_TCP); #endif - - error("SSL_write: %d (%s)\n", ssl_err, TCP_STRERROR); + logger(Core, Error, + "tcp_send(), SSL_write() failed with %d: %s", + ssl_err, TCP_STRERROR); g_network_error = True; return; } @@ -171,8 +172,8 @@ tcp_send(STREAM s) #ifdef WITH_SCARD scard_unlock(SCARD_LOCK_TCP); #endif - - error("send: %s\n", TCP_STRERROR); + logger(Core, Error, "tcp_send(), send() failed: %s", + TCP_STRERROR); g_network_error = True; return; } @@ -242,7 +243,8 @@ tcp_recv(STREAM s, uint32 length) { if (SSL_get_shutdown(g_ssl) & SSL_RECEIVED_SHUTDOWN) { - error("Remote peer initiated ssl shutdown.\n"); + logger(Core, Error, + "tcp_recv(), remote peer initiated ssl shutdown"); return NULL; } @@ -257,7 +259,8 @@ tcp_recv(STREAM s, uint32 length) } else if (ssl_err != SSL_ERROR_NONE) { - error("SSL_read: %d (%s)\n", ssl_err, TCP_STRERROR); + logger(Core, Error, "tcp_recv(), SSL_read() failed with %d: %s", + ssl_err, TCP_STRERROR); g_network_error = True; return NULL; } @@ -274,14 +277,15 @@ tcp_recv(STREAM s, uint32 length) } else { - error("recv: %s\n", TCP_STRERROR); + logger(Core, Error, "tcp_recv(), recv() failed: %s", + TCP_STRERROR); g_network_error = True; return NULL; } } else if (rcvd == 0) { - error("Connection closed\n"); + logger(Core, Error, "rcp_recv(), connection closed by peer"); return NULL; } } @@ -313,7 +317,8 @@ tcp_tls_connect(void) g_ssl_ctx = SSL_CTX_new(TLSv1_client_method()); if (g_ssl_ctx == NULL) { - error("tcp_tls_connect: SSL_CTX_new() failed to create TLS v1.0 context\n"); + logger(Core, Error, + "tcp_tls_connect(), SSL_CTX_new() failed to create TLS v1.0 context\n"); goto fail; } @@ -333,13 +338,13 @@ tcp_tls_connect(void) g_ssl = SSL_new(g_ssl_ctx); if (g_ssl == NULL) { - error("tcp_tls_connect: SSL_new() failed\n"); + logger(Core, Error, "tcp_tls_connect(), SSL_new() failed"); goto fail; } if (SSL_set_fd(g_ssl, g_sock) < 1) { - error("tcp_tls_connect: SSL_set_fd() failed\n"); + logger(Core, Error, "tcp_tls_connect(), SSL_set_fd() failed"); goto fail; } @@ -384,21 +389,22 @@ tcp_tls_get_server_pubkey(STREAM s) cert = SSL_get_peer_certificate(g_ssl); if (cert == NULL) { - error("tcp_tls_get_server_pubkey: SSL_get_peer_certificate() failed\n"); + logger(Core, Error, + "tcp_tls_get_server_pubkey(), SSL_get_peer_certificate() failed"); goto out; } pkey = X509_get_pubkey(cert); if (pkey == NULL) { - error("tcp_tls_get_server_pubkey: X509_get_pubkey() failed\n"); + logger(Core, Error, "tcp_tls_get_server_pubkey(), X509_get_pubkey() failed"); goto out; } s->size = i2d_PublicKey(pkey, NULL); if (s->size < 1) { - error("tcp_tls_get_server_pubkey: i2d_PublicKey() failed\n"); + logger(Core, Error, "tcp_tls_get_server_pubkey(), i2d_PublicKey() failed"); goto out; } @@ -437,7 +443,7 @@ tcp_connect(char *server) if ((n = getaddrinfo(server, tcp_port_rdp_s, &hints, &res))) { - error("getaddrinfo: %s\n", gai_strerror(n)); + logger(Core, Error, "tcp_connect(), getaddrinfo() failed: %s", gai_strerror(n)); return False; } @@ -459,7 +465,7 @@ tcp_connect(char *server) if (g_sock == -1) { - error("%s: unable to connect\n", server); + logger(Core, Error, "tcp_connect(), unable to connect to %s", server); return False; } @@ -474,13 +480,13 @@ tcp_connect(char *server) } else if ((servaddr.sin_addr.s_addr = inet_addr(server)) == INADDR_NONE) { - error("%s: unable to resolve host\n", server); + logger(Core, Error, "tcp_connect(), unable to resolve host '%s'", server); return False; } if ((g_sock = socket(AF_INET, SOCK_STREAM, 0)) < 0) { - error("socket: %s\n", TCP_STRERROR); + logger(Core, Error, "tcp_connect(), socket() failed: %s", TCP_STRERROR); return False; } @@ -490,7 +496,7 @@ tcp_connect(char *server) if (connect(g_sock, (struct sockaddr *) &servaddr, sizeof(struct sockaddr)) < 0) { if (!g_reconnect_loop) - error("connect: %s\n", TCP_STRERROR); + logger(Core, Error, "tcp_connect(), connect() failed: %s", TCP_STRERROR); TCP_CLOSE(g_sock); g_sock = -1; diff --git a/utils.c b/utils.c index d73bf25..22f181a 100644 --- a/utils.c +++ b/utils.c @@ -1,7 +1,7 @@ /* -*- c-basic-offset: 8 -*- rdesktop: A Remote Desktop Protocol client. Generic utility functions - Copyright 2013 Henrik Andersson for Cendio AB + Copyright 2013-2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -22,8 +22,11 @@ #include #include #include + #include "rdesktop.h" +#include "utils.h" + extern char g_codepage[16]; static RD_BOOL g_iconv_works = True; @@ -182,8 +185,9 @@ utils_locale_to_utf8(const char *src, size_t is, char *dest, size_t os) { if ((iconv_h = iconv_open("UTF-8", g_codepage)) == (iconv_t) - 1) { - warning("utils_string_to_utf8: iconv_open[%s -> %s] fail %p\n", - g_codepage, "UTF-8", iconv_h); + logger(Core, Warning, + "utils_string_to_utf8(), iconv_open[%s -> %s] fail %p", g_codepage, + "UTF-8", iconv_h); g_iconv_works = False; goto pass_trough_as_is; @@ -195,7 +199,7 @@ utils_locale_to_utf8(const char *src, size_t is, char *dest, size_t os) { iconv_close(iconv_h); iconv_h = (iconv_t) - 1; - warning("utils_string_to_utf8: iconv(1) fail, errno %d\n", errno); + logger(Core, Warning, "utils_string_to_utf8, iconv(1) fail, errno %d", errno); g_iconv_works = False; goto pass_trough_as_is; @@ -213,3 +217,153 @@ utils_locale_to_utf8(const char *src, size_t is, char *dest, size_t os) memcpy(dest, src, strlen(src) + 1); return 0; } + + +/* + * component logging + * + */ +#include + +static char *level[] = { + "debug", + "verbose", /* Verbose mesasge for end user, no prefixed lines */ + "warning", + "error", + "notice" /* Normal messages for end user, no prefixed lines */ +}; + +static char *subject[] = { + "UI", + "Keyboard", + "Clipboard", + "Sound", + "Protocol", + "Graphics", + "Core", + "SmartCard" +}; + +static log_level_t _logger_level = Warning; + +#define DEFAULT_LOGGER_SUBJECTS (1 << Core); + +#define ALL_LOGGER_SUBJECTS \ + (1 << GUI) \ + | (1 << Keyboard) \ + | (1 << Clipboard) \ + | (1 << Sound) \ + | (1 << Protocol) \ + | (1 << Graphics) \ + | (1 << Core) \ + | (1 << SmartCard) + + +static int _logger_subjects = DEFAULT_LOGGER_SUBJECTS; + +void +logger(log_subject_t s, log_level_t lvl, char *format, ...) +{ + va_list ap; + char buf[1024]; + + // Do not log if message is below global log level + if (_logger_level > lvl) + return; + + // Skip debug logging for non specified subjects + if (lvl < Verbose && !(_logger_subjects & (1 << s))) + return; + + va_start(ap, format); + vsnprintf(buf, sizeof(buf), format, ap); + + // Notice and Verbose messages goes without prefix + if (lvl == Notice || lvl == Verbose) + fprintf(stdout, "%s\n", buf); + else + fprintf(stderr, "%s(%s): %s\n", subject[s], level[lvl], buf); + + va_end(ap); +} + +void +logger_set_verbose(int verbose) +{ + if (_logger_level < Verbose) + return; + + if (verbose) + _logger_level = Verbose; + else + _logger_level = Warning; +} + +void +logger_set_subjects(char *subjects) +{ + int clear; + int bit; + char *pcs; + char *token; + + if (!subjects || !strlen(subjects)) + return; + + pcs = strdup(subjects); + + token = strtok(pcs, ","); + if (token == NULL) + { + free(pcs); + return; + } + + _logger_subjects = 0; + + do + { + + if (token == NULL) + break; + + bit = 0; + clear = (token[0] == '-') ? 1 : 0; + + if (clear == 1) + token++; + + if (strcmp(token, "All") == 0) + _logger_subjects |= ALL_LOGGER_SUBJECTS; + else if (strcmp(token, "UI") == 0) + bit = (1 << GUI); + else if (strcmp(token, "Keyboard") == 0) + bit = (1 << Keyboard); + else if (strcmp(token, "Clipboard") == 0) + bit = (1 << Clipboard); + else if (strcmp(token, "Sound") == 0) + bit = (1 << Sound); + else if (strcmp(token, "Protocol") == 0) + bit = (1 << Protocol); + else if (strcmp(token, "Graphics") == 0) + bit = (1 << Graphics); + else if (strcmp(token, "Core") == 0) + bit = (1 << Core); + else if (strcmp(token, "SmartCard") == 0) + bit = (1 << SmartCard); + else + continue; + + // set or clear logger subject bit + if (clear) + _logger_subjects &= ~bit; + else + _logger_subjects |= bit; + + } + while ((token = strtok(NULL, ",")) != NULL); + + _logger_level = Debug; + + free(pcs); +} diff --git a/utils.h b/utils.h new file mode 100644 index 0000000..23451cf --- /dev/null +++ b/utils.h @@ -0,0 +1,54 @@ +/* -*- c-basic-offset: 8 -*- + rdesktop: A Remote Desktop Protocol client. + + Copyright 2017 Henrik Andersson for Cendio AB + + This program is free software: you can redistribute it and/or modify + it under the terms of the GNU General Public License as published by + the Free Software Foundation, either version 3 of the License, or + (at your option) any later version. + + This program is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU General Public License for more details. + + You should have received a copy of the GNU General Public License + along with this program. If not, see . +*/ + +#ifndef _utils_h +#define _utils_h + +char *utils_string_escape(const char *str); +char *utils_string_unescape(const char *str); +int utils_locale_to_utf8(const char *src, size_t is, char *dest, size_t os); +int utils_mkdir_safe(const char *path, int mask); +int utils_mkdir_p(const char *path, int mask); + +typedef enum log_level_t +{ + Debug = 0, + Verbose, + Warning, + Error, + Notice /* special message level for end user messages with prefix */ +} log_level_t; + +typedef enum log_subject_t +{ + GUI = 0, + Keyboard, + Clipboard, + Sound, + Protocol, + Graphics, + Core, + SmartCard +} log_subject_t; + +void logger(log_subject_t c, log_level_t lvl, char *format, ...); +void logger_set_verbose(int verbose); +void logger_set_subjects(char *subjects); + +#endif /* _utils_h */ diff --git a/xclip.c b/xclip.c index 9798055..086a1cd 100644 --- a/xclip.c +++ b/xclip.c @@ -4,6 +4,7 @@ Copyright 2003-2008 Erik Forsberg for Cendio AB Copyright (C) Matthew Chapman 2003-2008 Copyright 2006-2011 Pierre Ossman for Cendio AB + Copyright 2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -219,7 +220,10 @@ xclip_provide_selection(XSelectionRequestEvent * req, Atom type, unsigned int fo { XEvent xev; - DEBUG_CLIPBOARD(("xclip_provide_selection: requestor=0x%08x, target=%s, property=%s, length=%u\n", (unsigned) req->requestor, XGetAtomName(g_display, req->target), XGetAtomName(g_display, req->property), (unsigned) length)); + logger(Clipboard, Debug, + "xclip_provide_selection(), requestor=0x%08x, target=%s, property=%s, length=%u", + (unsigned) req->requestor, XGetAtomName(g_display, req->target), + XGetAtomName(g_display, req->property), (unsigned) length); XChangeProperty(g_display, req->requestor, req->property, type, format, PropModeReplace, data, length); @@ -243,9 +247,10 @@ xclip_refuse_selection(XSelectionRequestEvent * req) { XEvent xev; - DEBUG_CLIPBOARD(("xclip_refuse_selection: requestor=0x%08x, target=%s, property=%s\n", - (unsigned) req->requestor, XGetAtomName(g_display, req->target), - XGetAtomName(g_display, req->property))); + logger(Clipboard, Debug, + "xclip_refuse_selection(), requestor=0x%08x, target=%s, property=%s", + (unsigned) req->requestor, XGetAtomName(g_display, req->target), + XGetAtomName(g_display, req->property)); xev.xselection.type = SelectionNotify; xev.xselection.serial = 0; @@ -286,8 +291,8 @@ helper_cliprdr_send_empty_response() static RD_BOOL xclip_send_data_with_convert(uint8 * source, size_t source_size, Atom target) { - DEBUG_CLIPBOARD(("xclip_send_data_with_convert: target=%s, size=%u\n", - XGetAtomName(g_display, target), (unsigned) source_size)); + logger(Clipboard, Debug, "xclip_send_data_with_convert(), target=%s, size=%u", + XGetAtomName(g_display, target), (unsigned) source_size); #ifdef USE_UNICODE_CLIPBOARD if (target == format_string_atom || @@ -317,7 +322,9 @@ xclip_send_data_with_convert(uint8 * source, size_t source_size, Atom target) cd = iconv_open(WINDOWS_CODEPAGE, locale_charset); if (cd == (iconv_t) - 1) { - DEBUG_CLIPBOARD(("Locale charset %s not found in iconv. Unable to convert clipboard text.\n", locale_charset)); + logger(Clipboard, Error, + "xclip_send_data_with_convert(), convert failed, locale charset %s not found", + locale_charset); return False; } unicode_buffer_size = source_size * 4; @@ -362,8 +369,9 @@ xclip_send_data_with_convert(uint8 * source, size_t source_size, Atom target) translated_data = utf16_lf2crlf((uint8 *) unicode_buffer, &translated_data_size); if (translated_data != NULL) { - DEBUG_CLIPBOARD(("Sending Unicode string of %d bytes\n", - translated_data_size)); + logger(Clipboard, Debug, + "xclip_send_data_with_convert(), sending unicode string of %d bytes", + translated_data_size); helper_cliprdr_send_response(translated_data, translated_data_size); xfree(translated_data); /* Not the same thing as XFree! */ } @@ -381,7 +389,8 @@ xclip_send_data_with_convert(uint8 * source, size_t source_size, Atom target) if (rdp_clipboard_request_format != RDP_CF_TEXT) return False; - DEBUG_CLIPBOARD(("Translating linebreaks before sending data\n")); + logger(Clipboard, Debug, + "xclip_send_data_with_convert(), translating linebreaks before sending data"); translated_data = lf2crlf(source, &length); if (translated_data != NULL) { @@ -426,12 +435,13 @@ xclip_probe_selections() if (probing_selections) { - DEBUG_CLIPBOARD(("Already probing selections. Scheduling reprobe.\n")); + logger(Clipboard, Debug, + "xclip_probe_selection(), already probing selections, scheduling reprobe"); reprobe_selections = True; return; } - DEBUG_CLIPBOARD(("Probing selections.\n")); + logger(Clipboard, Debug, "xclip_probe_selection(), probing selections"); probing_selections = True; reprobe_selections = False; @@ -477,7 +487,7 @@ xclip_probe_selections() return; } - DEBUG_CLIPBOARD(("No owner of any selection.\n")); + logger(Clipboard, Debug, "xclip_probe_selection(), no owner of any selection"); /* FIXME: Without XFIXES, we cannot reliably know the formats offered by an @@ -507,10 +517,10 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) if (event->property == None) goto fail; - DEBUG_CLIPBOARD(("xclip_handle_SelectionNotify: selection=%s, target=%s, property=%s\n", - XGetAtomName(g_display, event->selection), - XGetAtomName(g_display, event->target), - XGetAtomName(g_display, event->property))); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), selection=%s, target=%s, property=%s", + XGetAtomName(g_display, event->selection), XGetAtomName(g_display, event->target), + XGetAtomName(g_display, event->property)); if (event->target == timestamp_atom) { @@ -532,7 +542,8 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) if ((res != Success) || (nitems != 1) || (format != 32)) { - DEBUG_CLIPBOARD(("XGetWindowProperty failed!\n")); + logger(Clipboard, Error, + "xclip_handle_SelectionNotify(), XGetWindowProperty failed"); goto fail; } @@ -542,8 +553,9 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) if (primary_timestamp == 0) primary_timestamp++; XDeleteProperty(g_display, g_wnd, rdesktop_primary_timestamp_target_atom); - DEBUG_CLIPBOARD(("Got PRIMARY timestamp: %u\n", - (unsigned) primary_timestamp)); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), got PRIMARY timestamp: %u", + (unsigned) primary_timestamp); } else { @@ -551,8 +563,9 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) if (clipboard_timestamp == 0) clipboard_timestamp++; XDeleteProperty(g_display, g_wnd, rdesktop_clipboard_timestamp_target_atom); - DEBUG_CLIPBOARD(("Got CLIPBOARD timestamp: %u\n", - (unsigned) clipboard_timestamp)); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), got CLIPBOARD timestamp: %u", + (unsigned) clipboard_timestamp); } XFree(data); @@ -561,14 +574,16 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) { if (primary_timestamp > clipboard_timestamp) { - DEBUG_CLIPBOARD(("PRIMARY is most recent selection.\n")); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), PRIMARY is most recent selection"); XConvertSelection(g_display, primary_atom, targets_atom, rdesktop_clipboard_target_atom, g_wnd, event->time); } else { - DEBUG_CLIPBOARD(("CLIPBOARD is most recent selection.\n")); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), CLIPBOARD is most recent selection"); XConvertSelection(g_display, clipboard_atom, targets_atom, rdesktop_clipboard_target_atom, g_wnd, event->time); @@ -593,13 +608,14 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) if (res != Success) { - DEBUG_CLIPBOARD(("XGetWindowProperty failed!\n")); + logger(Clipboard, Error, + "xclip_handle_SelectionNotify(), XGetWindowProperty() failed"); goto fail; } if (type == incr_atom) { - DEBUG_CLIPBOARD(("Received INCR.\n")); + logger(Clipboard, Debug, "xclip_handle_SelectionNotify(), received INCR"); XGetWindowAttributes(g_display, g_wnd, &wa); if ((wa.your_event_mask | PropertyChangeMask) != wa.your_event_mask) @@ -627,13 +643,15 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) supported_targets = (Atom *) data; for (i = 0; i < nitems; i++) { - DEBUG_CLIPBOARD(("Target %d: %s\n", i, - XGetAtomName(g_display, supported_targets[i]))); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), target %d: %s", i, + XGetAtomName(g_display, supported_targets[i])); if (supported_targets[i] == format_string_atom) { if (text_target_satisfaction < 1) { - DEBUG_CLIPBOARD(("Other party supports STRING, choosing that as best_target\n")); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), other party supports STRING, choosing that as best_target"); best_text_target = supported_targets[i]; text_target_satisfaction = 1; } @@ -643,7 +661,8 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) { if (text_target_satisfaction < 2) { - DEBUG_CLIPBOARD(("Other party supports text/unicode, choosing that as best_target\n")); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), other party supports text/unicode, choosing that as best_target"); best_text_target = supported_targets[i]; text_target_satisfaction = 2; } @@ -652,7 +671,8 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) { if (text_target_satisfaction < 3) { - DEBUG_CLIPBOARD(("Other party supports UTF8_STRING, choosing that as best_target\n")); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), other party supports UTF8_STRING, choosing that as best_target"); best_text_target = supported_targets[i]; text_target_satisfaction = 3; } @@ -662,7 +682,8 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) { if (probing_selections && (text_target_satisfaction < 4)) { - DEBUG_CLIPBOARD(("Other party supports native formats, choosing that as best_target\n")); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), other party supports native formats, choosing that as best_target"); best_text_target = supported_targets[i]; text_target_satisfaction = 4; } @@ -683,7 +704,8 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) } else { - DEBUG_CLIPBOARD(("Unable to find a textual target to satisfy RDP clipboard text request\n")); + logger(Clipboard, Error, + "xclip_handle_SelectionNotify(), unable to find a textual target to satisfy RDP clipboard text request"); goto fail; } } @@ -709,7 +731,8 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) if (primary_owner != clipboard_owner) goto fail; - DEBUG_CLIPBOARD(("Got fellow rdesktop formats\n")); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), got fellow rdesktop formats"); probing_selections = False; rdesktop_is_selection_owner = True; cliprdr_send_native_format_announce(data, nitems); @@ -730,7 +753,8 @@ xclip_handle_SelectionNotify(XSelectionEvent * event) xclip_clear_target_props(); if (probing_selections) { - DEBUG_CLIPBOARD(("Unable to find suitable target. Using default text format.\n")); + logger(Clipboard, Debug, + "xclip_handle_SelectionNotify(), unable to find suitable target, using default text format"); probing_selections = False; rdesktop_is_selection_owner = False; @@ -759,10 +783,10 @@ xclip_handle_SelectionRequest(XSelectionRequestEvent * event) int format, res; Atom type; - DEBUG_CLIPBOARD(("xclip_handle_SelectionRequest: selection=%s, target=%s, property=%s\n", - XGetAtomName(g_display, event->selection), - XGetAtomName(g_display, event->target), - XGetAtomName(g_display, event->property))); + logger(Clipboard, Debug, + "xclip_handle_SelectionRequest(), selection=%s, target=%s, property=%s", + XGetAtomName(g_display, event->selection), XGetAtomName(g_display, event->target), + XGetAtomName(g_display, event->property)); if (event->target == targets_atom) { @@ -785,7 +809,8 @@ xclip_handle_SelectionRequest(XSelectionRequestEvent * event) handle one such request at a time. */ if (has_selection_request) { - DEBUG_CLIPBOARD(("Error: Another clipboard request was already sent to the RDP server and not yet responded. Refusing this request.\n")); + logger(Clipboard, Warning, + "xclip_handle_SelectionRequest(), overlapping clipboard request, skipping."); xclip_refuse_selection(event); return; } @@ -799,7 +824,8 @@ xclip_handle_SelectionRequest(XSelectionRequestEvent * event) &prop_return); if (res != Success || (!prop_return)) { - DEBUG_CLIPBOARD(("Requested native format but didn't specifiy which.\n")); + logger(Clipboard, Error, + "xclip_handle_SelectionRequest(), requested native format without specify which"); xclip_refuse_selection(event); return; } @@ -817,7 +843,8 @@ xclip_handle_SelectionRequest(XSelectionRequestEvent * event) #ifdef USE_UNICODE_CLIPBOARD format = CF_UNICODETEXT; #else - DEBUG_CLIPBOARD(("Requested target unavailable due to lack of Unicode support. (It was not in TARGETS, so why did you ask for it?!)\n")); + logger(Clipboard, Warning, + "xclip_handle_SelectionRequest(), target unavailable due to lack of unicode support"); xclip_refuse_selection(event); return; #endif @@ -829,7 +856,9 @@ xclip_handle_SelectionRequest(XSelectionRequestEvent * event) } else { - DEBUG_CLIPBOARD(("Requested target unavailable. (It was not in TARGETS, so why did you ask for it?!)\n")); + logger(Clipboard, Warning, + "xclip_handle_SelectionRequest(), unsupported target format, target='%s'", + XGetAtomName(g_display, event->target)); xclip_refuse_selection(event); return; } @@ -851,7 +880,7 @@ xclip_handle_SelectionRequest(XSelectionRequestEvent * event) void xclip_handle_SelectionClear(void) { - DEBUG_CLIPBOARD(("xclip_handle_SelectionClear\n")); + logger(Clipboard, Debug, "xclip_handle_SelectionClear()"); xclip_notify_change(); xclip_probe_selections(); } @@ -870,7 +899,7 @@ xclip_handle_PropertyNotify(XPropertyEvent * event) if (event->state == PropertyNewValue && g_waiting_for_INCR) { - DEBUG_CLIPBOARD(("x_clip_handle_PropertyNotify: g_waiting_for_INCR != 0\n")); + logger(Clipboard, Debug, "xclip_handle_PropertyNotify(), g_waiting_for_INCR != 0"); while (bytes_left > 0) { @@ -940,11 +969,11 @@ ui_clip_format_announce(uint8 * data, uint32 length) XSetSelectionOwner(g_display, primary_atom, g_wnd, acquire_time); if (XGetSelectionOwner(g_display, primary_atom) != g_wnd) - warning("Failed to aquire ownership of PRIMARY clipboard\n"); + logger(Clipboard, Warning, "failed to aquire ownership of PRIMARY clipboard"); XSetSelectionOwner(g_display, clipboard_atom, g_wnd, acquire_time); if (XGetSelectionOwner(g_display, clipboard_atom) != g_wnd) - warning("Failed to aquire ownership of CLIPBOARD clipboard\n"); + logger(Clipboard, Warning, "failed to aquire ownership of CLIPBOARD clipboard"); if (formats_data) xfree(formats_data); @@ -1024,7 +1053,9 @@ ui_clip_handle_data(uint8 * data, uint32 length) } else { - DEBUG_CLIPBOARD(("ui_clip_handle_data: BUG! I don't know how to convert selection target %s!\n", XGetAtomName(g_display, selection_request.target))); + logger(Clipboard, Debug, + "ui_clip_handle_data(), no handler for selection target '%s'", + XGetAtomName(g_display, selection_request.target)); xclip_refuse_selection(&selection_request); has_selection_request = False; return; @@ -1049,12 +1080,13 @@ ui_clip_request_data(uint32 format) { Window primary_owner, clipboard_owner; - DEBUG_CLIPBOARD(("Request from server for format %d\n", format)); + logger(Clipboard, Debug, "request from server for format %d", format); rdp_clipboard_request_format = format; if (probing_selections) { - DEBUG_CLIPBOARD(("ui_clip_request_data: Selection probe in progress. Cannot handle request.\n")); + logger(Clipboard, Debug, + "ui_clip_request_data(), selection probe in progress, cannot handle request"); helper_cliprdr_send_empty_response(); return; } @@ -1127,7 +1159,7 @@ ui_clip_set_mode(const char *optarg) auto_mode = False; else { - warning("Invalid clipboard mode '%s'.\n", optarg); + logger(Clipboard, Warning, "invalid clipboard mode '%s'", optarg); g_rdpclip = False; } } diff --git a/xkeymap.c b/xkeymap.c index 240e31d..6084e12 100644 --- a/xkeymap.c +++ b/xkeymap.c @@ -4,7 +4,7 @@ Copyright (C) Matthew Chapman 1999-2008 Copyright 2003-2008 Peter Astrand for Cendio AB - Copyright 2014 Henrik Andersson for Cendio AB + Copyright 2014-2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -165,12 +165,13 @@ add_to_keymap(char *keyname, uint8 scancode, uint16 modifiers, char *mapname) keysym = XStringToKeysym(keyname); if (keysym == NoSymbol) { - DEBUG_KBD(("Bad keysym \"%s\" in keymap %s (ignoring)\n", keyname, mapname)); + logger(Keyboard, Error, "add_to_keymap(), ignoring bad keysym '%s' in keymap %s", + keyname, mapname); return; } - DEBUG_KBD(("Adding translation, keysym=0x%x, scancode=0x%x, " - "modifiers=0x%x\n", (unsigned int) keysym, scancode, modifiers)); + logger(Keyboard, Debug, "add_to_keymap(), adding translation, keysym=0x%x, scancode=0x%x, " + "modifiers=0x%x", (unsigned int) keysym, scancode, modifiers); /* Make a new entry in the table */ entry = new_key_translation_entry(keysym); @@ -206,11 +207,13 @@ add_sequence(char *rest, char *mapname) keysym = XStringToKeysym(keyname); if (keysym == NoSymbol) { - DEBUG_KBD(("Bad keysym \"%s\" in keymap %s (ignoring line)\n", keyname, mapname)); + logger(Keyboard, Error, "add_sequence(), ignoring bad keysym '%s' in keymap %s", + keyname, mapname); return; } - DEBUG_KBD(("Adding sequence for keysym (0x%lx, %s) -> ", keysym, keyname)); + logger(Keyboard, Debug, "add_sequence(), adding squence for keysym '%s' (0x%lx)", keyname, + keysym); entry = new_key_translation_entry(keysym); prev_next = &(entry->tr); @@ -233,8 +236,9 @@ add_sequence(char *rest, char *mapname) seq_keysym = XStringToKeysym(keyname); if (seq_keysym == NoSymbol) { - DEBUG_KBD(("Bad keysym \"%s\" in keymap %s (ignoring line)\n", keyname, - mapname)); + logger(Keyboard, Error, + "add_sequence(), ignoring line with bad keysym '%s' in keymap %s", + keyname, mapname); delete_key_translation_entry(keysym); return; } @@ -250,10 +254,7 @@ add_sequence(char *rest, char *mapname) *prev_next = tr; prev_next = &tr->next; tr->seq_keysym = seq_keysym; - - DEBUG_KBD(("0x%x, ", (unsigned int) seq_keysym)); } - DEBUG_KBD(("\n")); } RD_BOOL @@ -387,7 +388,7 @@ xkeymap_read(char *mapname) fp = xkeymap_open(mapname); if (fp == NULL) { - error("Failed to open keymap %s\n", mapname); + logger(Keyboard, Error, "xkeymap_read(), failed to open keymap %s", mapname); return False; } @@ -421,14 +422,14 @@ xkeymap_read(char *mapname) if (str_startswith(line, "map ")) { g_keylayout = strtoul(line + sizeof("map ") - 1, NULL, 16); - DEBUG_KBD(("Keylayout 0x%x\n", g_keylayout)); + logger(Keyboard, Debug, "xkeymap_read(), Keylayout 0x%x", g_keylayout); continue; } /* compose */ if (str_startswith(line, "enable_compose")) { - DEBUG_KBD(("Enabling compose handling\n")); + logger(Keyboard, Debug, "xkeymap_read(), enabling compose handling"); g_enable_compose = True; continue; } @@ -444,7 +445,8 @@ xkeymap_read(char *mapname) if (str_startswith(line, "keyboard_type ")) { g_keyboard_type = strtol(line + sizeof("keyboard_type ") - 1, NULL, 16); - DEBUG_KBD(("keyboard_type 0x%x\n", g_keyboard_type)); + logger(Keyboard, Debug, "xkeymap_read(), keyboard_type 0x%x", + g_keyboard_type); continue; } @@ -453,7 +455,8 @@ xkeymap_read(char *mapname) { g_keyboard_subtype = strtol(line + sizeof("keyboard_subtype ") - 1, NULL, 16); - DEBUG_KBD(("keyboard_subtype 0x%x\n", g_keyboard_subtype)); + logger(Keyboard, Debug, "xkeymap_read(), keyboard_subtype 0x%x", + g_keyboard_subtype); continue; } @@ -462,7 +465,8 @@ xkeymap_read(char *mapname) { g_keyboard_functionkeys = strtol(line + sizeof("keyboard_functionkeys ") - 1, NULL, 16); - DEBUG_KBD(("keyboard_functionkeys 0x%x\n", g_keyboard_functionkeys)); + logger(Keyboard, Debug, "xkeymap_read(), keyboard_functionkeys 0x%x", + g_keyboard_functionkeys); continue; } @@ -477,7 +481,8 @@ xkeymap_read(char *mapname) p = strchr(line, ' '); if (p == NULL) { - error("Bad line %d in keymap %s\n", line_num, mapname); + logger(Keyboard, Error, "xkeymap_read(), bad line %d in keymap %s", + line_num, mapname); continue; } else @@ -746,7 +751,7 @@ xkeymap_translate_key(uint32 keysym, unsigned int keycode, unsigned int state) { if (MASK_HAS_BITS(tr.modifiers, MapInhibitMask)) { - DEBUG_KBD(("Inhibiting key\n")); + logger(Keyboard, Debug, "xkeymap_translate_key(), inhibiting key"); tr.scancode = 0; return tr; } @@ -771,19 +776,21 @@ xkeymap_translate_key(uint32 keysym, unsigned int keycode, unsigned int state) && MASK_HAS_BITS(remote_modifier_state, MapCtrlMask) && !MASK_HAS_BITS(state, ShiftMask)) { - DEBUG_KBD(("Non-physical Shift + Ctrl pressed, releasing Shift\n")); + logger(Keyboard, Debug, + "xkeymap_translate_key(), non-physical Shift + Ctrl pressed, releasing Shift"); MASK_REMOVE_BITS(tr.modifiers, MapShiftMask); } - DEBUG_KBD(("Found scancode translation, scancode=0x%x, modifiers=0x%x\n", - tr.scancode, tr.modifiers)); + logger(Keyboard, Debug, + "xkeymap_translate_key(), found scancode translation, scancode=0x%x, modifiers=0x%x", + tr.scancode, tr.modifiers); } } else { if (keymap_loaded) - warning("No translation for (keysym 0x%lx, %s)\n", keysym, - get_ksname(keysym)); + logger(Keyboard, Warning, "No translation for (keysym 0x%lx, %s)", keysym, + get_ksname(keysym)); /* not in keymap, try to interpret the raw scancode */ if (((int) keycode >= min_keycode) && (keycode <= 0x60)) @@ -798,11 +805,11 @@ xkeymap_translate_key(uint32 keysym, unsigned int keycode, unsigned int state) tr.modifiers = MapLeftShiftMask; } - DEBUG_KBD(("Sending guessed scancode 0x%x\n", tr.scancode)); + logger(Keyboard, Debug, "Sending guessed scancode 0x%x", tr.scancode); } else { - DEBUG_KBD(("No good guess for keycode 0x%x found\n", keycode)); + logger(Keyboard, Debug, "No good guess for keycode 0x%x found", keycode); } } @@ -857,12 +864,13 @@ xkeymap_send_keys(uint32 keysym, unsigned int keycode, unsigned int state, uint3 ptr = &tr; do { - DEBUG_KBD(("Handling sequence element, keysym=0x%x\n", - (unsigned int) ptr->seq_keysym)); + logger(Keyboard, Debug, + "xkeymap_send_keys(), handling sequence element, keysym=0x%x", + (unsigned int) ptr->seq_keysym); if (nesting++ > 32) { - error("Sequence nesting too deep\n"); + logger(Keyboard, Error, "Sequence nesting too deep"); return; } @@ -947,13 +955,15 @@ ensure_remote_modifiers(uint32 ev_time, key_translation tr) if (MASK_HAS_BITS(tr.modifiers, MapNumLockMask)) { - DEBUG_KBD(("Remote NumLock state is incorrect, activating NumLock.\n")); + logger(Keyboard, Debug, + "ensure_remote_modifiers(), remote NumLock state is incorrect, activating NumLock"); new_remote_state = KBD_FLAG_NUMLOCK; remote_modifier_state = MapNumLockMask; } else { - DEBUG_KBD(("Remote NumLock state is incorrect, deactivating NumLock.\n")); + logger(Keyboard, Debug, + "ensure_remote_modifiers(), remote NumLock state is incorrect, deactivating NumLock."); new_remote_state = 0; remote_modifier_state = 0; } @@ -1082,11 +1092,9 @@ reset_modifier_keys() static void update_modifier_state(uint8 scancode, RD_BOOL pressed) { -#ifdef WITH_DEBUG_KBD uint16 old_modifier_state; old_modifier_state = remote_modifier_state; -#endif switch (scancode) { @@ -1128,15 +1136,14 @@ update_modifier_state(uint8 scancode, RD_BOOL pressed) } } -#ifdef WITH_DEBUG_KBD if (old_modifier_state != remote_modifier_state) { - DEBUG_KBD(("Before updating modifier_state:0x%x, pressed=0x%x\n", - old_modifier_state, pressed)); - DEBUG_KBD(("After updating modifier_state:0x%x\n", remote_modifier_state)); + logger(Keyboard, Debug, + "update_modifier_state(), before modifier_state:0x%x, pressed=0x%x", + old_modifier_state, pressed); + logger(Keyboard, Debug, "update_modifier_state(), after modifier_state:0x%x", + remote_modifier_state); } -#endif - } /* Send keyboard input */ @@ -1147,14 +1154,16 @@ rdp_send_scancode(uint32 time, uint16 flags, uint8 scancode) if (scancode & SCANCODE_EXTENDED) { - DEBUG_KBD(("Sending extended scancode=0x%x, flags=0x%x\n", - scancode & ~SCANCODE_EXTENDED, flags)); + logger(Keyboard, Debug, + "rdp_send_scancode(), sending extended scancode=0x%x, flags=0x%x", + scancode & ~SCANCODE_EXTENDED, flags); rdp_send_input(time, RDP_INPUT_SCANCODE, flags | KBD_FLAG_EXT, scancode & ~SCANCODE_EXTENDED, 0); } else { - DEBUG_KBD(("Sending scancode=0x%x, flags=0x%x\n", scancode, flags)); + logger(Keyboard, Debug, "rdp_send_scancode(), sending scancode=0x%x, flags=0x%x", + scancode, flags); rdp_send_input(time, RDP_INPUT_SCANCODE, flags, scancode, 0); } } diff --git a/xwin.c b/xwin.c index 0bc4fe5..0778544 100644 --- a/xwin.c +++ b/xwin.c @@ -4,7 +4,7 @@ Copyright (C) Matthew Chapman 1999-2008 Copyright 2007-2008 Pierre Ossman for Cendio AB Copyright 2002-2011 Peter Astrand for Cendio AB - Copyright 2012-2013 Henrik Andersson for Cendio AB + Copyright 2012-2017 Henrik Andersson for Cendio AB This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by @@ -533,7 +533,8 @@ mwm_hide_decorations(Window wnd) hintsatom = XInternAtom(g_display, "_MOTIF_WM_HINTS", False); if (!hintsatom) { - warning("Failed to get atom _MOTIF_WM_HINTS: probably your window manager does not support MWM hints\n"); + logger(GUI, Warning, + "Failed to get atom _MOTIF_WM_HINTS: probably your window manager does not support MWM hints\n"); return; } @@ -602,7 +603,8 @@ sw_wait_configurenotify(Window wnd, unsigned long serial) if (!got) { - warning("Broken Window Manager: Timeout while waiting for ConfigureNotify\n"); + logger(GUI, Warning, + "Broken Window Manager: Timeout while waiting for ConfigureNotify\n"); } } @@ -623,7 +625,7 @@ sw_get_toplevel(Window wnd) } else if (!parent) { - warning("Internal error: sw_get_toplevel called with root window\n"); + logger(GUI, Error, "sw_get_toplevel called with root window\n"); } wnd = parent; @@ -668,12 +670,12 @@ sw_window_is_behind(Window wnd, Window behind) if (!found_wnd) { - warning("sw_window_is_behind: Unable to find window 0x%lx\n", wnd); + logger(GUI, Warning, "sw_window_is_behind: Unable to find window 0x%lx", wnd); if (!found_behind) { - warning("sw_window_is_behind: Unable to find behind window 0x%lx\n", - behind); + logger(GUI, Warning, + "sw_window_is_behind: Unable to find behind window 0x%lx", behind); } } @@ -749,7 +751,7 @@ seamless_restack_test() if (!sw_window_is_behind(wnds[0], wnds[1]) || !sw_window_is_behind(wnds[2], wnds[1])) { /* Ok, technically a WM is allowed to stack windows arbitrarily, but... */ - warning("Broken Window Manager: Unable to test window restacking\n"); + logger(GUI, Warning, "Broken Window Manager: Unable to test window restacking"); g_seamless_broken_restack = True; for (i = 0; i < 3; i++) XDestroyWindow(g_display, wnds[i]); @@ -769,12 +771,14 @@ seamless_restack_test() bottom */ if (!sw_window_is_behind(wnds[1], wnds[0])) { - warning("Broken Window Manager: doesn't handle restack (restack request was ignored)\n"); + logger(GUI, Warning, + "Broken Window Manager: doesn't handle restack (restack request was ignored)"); g_seamless_broken_restack = True; } else if (sw_window_is_behind(wnds[1], wnds[2])) { - warning("Broken Window Manager: doesn't handle restack (window was moved to bottom)\n"); + logger(GUI, Warning, + "Broken Window Manager: doesn't handle restack (window was moved to bottom)"); g_seamless_broken_restack = True; } @@ -1627,7 +1631,7 @@ select_visual(int screen_num) pfm = XListPixmapFormats(g_display, &pixmap_formats_count); if (pfm == NULL) { - error("Unable to get list of pixmap formats from display.\n"); + logger(GUI, Error, "Unable to get list of pixmap formats from display"); XCloseDisplay(g_display); return False; } @@ -1749,7 +1753,8 @@ select_visual(int screen_num) &template, &visuals_count); if (vmatches == NULL) { - error("No usable TrueColor or PseudoColor visuals on this display.\n"); + logger(GUI, Error, + "No usable TrueColor or PseudoColor visuals on this display"); XCloseDisplay(g_display); XFree(pfm); return False; @@ -1864,7 +1869,7 @@ ui_init(void) g_display = XOpenDisplay(NULL); if (g_display == NULL) { - error("Failed to open display: %s\n", XDisplayName(NULL)); + logger(GUI, Error, "ui_init(), failed to open X11 display: %s", XDisplayName(NULL)); return False; } @@ -1885,17 +1890,20 @@ ui_init(void) if (g_no_translate_image) { - DEBUG(("Performance optimization possible: avoiding image translation (colour depth conversion).\n")); + logger(GUI, Debug, + "Performance optimization possible: avoiding image translation (colour depth conversion)"); } if (g_server_depth > g_bpp) { - warning("Remote desktop colour depth %d higher than display colour depth %d.\n", - g_server_depth, g_bpp); + logger(GUI, Warning, + "Remote desktop colour depth %d higher than display colour depth %d", + g_server_depth, g_bpp); } - DEBUG(("RDP depth: %d, display depth: %d, display bpp: %d, X server BE: %d, host BE: %d\n", - g_server_depth, g_depth, g_bpp, g_xserver_be, g_host_be)); + logger(GUI, Debug, + "RDP depth: %d, display depth: %d, display bpp: %d, X server BE: %d, host BE: %d\n", + g_server_depth, g_depth, g_bpp, g_xserver_be, g_host_be); if (!g_owncolmap) { @@ -1903,12 +1911,14 @@ ui_init(void) XCreateColormap(g_display, RootWindowOfScreen(g_screen), g_visual, AllocNone); if (g_depth <= 8) - warning("Display colour depth is %d bit: you may want to use -C for a private colourmap.\n", g_depth); + logger(GUI, Warning, + "Display colour depth is %d bit: you may want to use -C for a private colourmap", + g_depth); } if ((!g_ownbackstore) && (DoesBackingStore(g_screen) != Always)) { - warning("External BackingStore not available. Using internal.\n"); + logger(GUI, Warning, "External BackingStore not available. Using internal"); g_ownbackstore = True; } @@ -1927,8 +1937,6 @@ ui_init(void) seamless_init(); } - DEBUG_RDP5(("server bpp %d client bpp %d depth %d\n", g_server_depth, g_bpp, g_depth)); - return True; } @@ -1968,7 +1976,8 @@ ui_init_connection(void) } else { - warning("Failed to get workarea: probably your window manager does not support extended hints\n"); + logger(GUI, Warning, + "Failed to get workarea: probably your window manager does not support extended hints\n"); g_width = WidthOfScreen(g_screen); g_height = HeightOfScreen(g_screen); } @@ -2368,7 +2377,7 @@ xwin_process_events(void) if ((g_IC != NULL) && (XFilterEvent(&xevent, None) == True)) { - DEBUG_KBD(("Filtering event\n")); + logger(GUI, Debug, "xwin_process_events(), filtering event"); continue; } @@ -2419,21 +2428,23 @@ xwin_process_events(void) &status); if (!((status == XLookupKeySym) || (status == XLookupBoth))) { - error("XmbLookupString failed with status 0x%x\n", - status); + logger(GUI, Error, + "XmbLookupString failed with status 0x%x\n", + status); break; } } else { /* Plain old XLookupString */ - DEBUG_KBD(("\nNo input context, using XLookupString\n")); - XLookupString((XKeyEvent *) & xevent, - str, sizeof(str), &keysym, NULL); + logger(Keyboard, Debug, + "No input context, using fallback XLookupString"); + XLookupString((XKeyEvent *) & xevent, str, sizeof(str), + &keysym, NULL); } - DEBUG_KBD(("KeyPress for keysym (0x%lx, %s)\n", keysym, - get_ksname(keysym))); + logger(Keyboard, Debug, "KeyPress for keysym (0x%lx, %s)", keysym, + get_ksname(keysym)); set_keypress_keysym(xevent.xkey.keycode, keysym); ev_time = time(NULL); @@ -2449,8 +2460,8 @@ xwin_process_events(void) XLookupString((XKeyEvent *) & xevent, str, sizeof(str), &keysym, NULL); - DEBUG_KBD(("\nKeyRelease for keysym (0x%lx, %s)\n", keysym, - get_ksname(keysym))); + logger(Keyboard, Debug, "KeyRelease for keysym (0x%lx, %s)", keysym, + get_ksname(keysym)); keysym = reset_keypress_keysym(xevent.xkey.keycode, keysym); ev_time = time(NULL); @@ -2741,7 +2752,8 @@ ui_select(int rdp_socket) switch (select(n, &rfds, &wfds, NULL, &tv)) { case -1: - error("select: %s\n", strerror(errno)); + logger(GUI, Error, "ui_select(), select failed: %s", + strerror(errno)); case 0: #ifdef WITH_RDPSND @@ -2935,7 +2947,7 @@ get_next_xor_pixel(uint8 * xormask, int bpp, int *k) (*k) += 4; break; default: - error("unknown bpp in get_next_xor_pixel %d\n", bpp); + logger(GUI, Warning, "get_next_xor_pixel(), unhandled bpp=%d", bpp); break; } return rv; @@ -3291,7 +3303,8 @@ ui_patblt(uint8 opcode, break; default: - unimpl("brush %d\n", brush->style); + logger(GUI, Warning, "Unimplemented support for brush type %d", + brush->style); } RESET_FUNCTION(opcode); @@ -3370,7 +3383,7 @@ ui_triblt(uint8 opcode, break; default: - unimpl("triblt 0x%x\n", opcode); + logger(GUI, Warning, "Unimplemented triblit opcode 0x%x", opcode); ui_memblt(ROP2_COPY, x, y, cx, cy, src, srcx, srcy); } } @@ -3420,7 +3433,7 @@ ui_polygon(uint8 opcode, XSetFillRule(g_display, g_gc, WindingRule); break; default: - unimpl("fill mode %d\n", fillmode); + logger(GUI, Warning, "Unimplemented fill mode %d", fillmode); } if (brush) @@ -3492,7 +3505,7 @@ ui_polygon(uint8 opcode, break; default: - unimpl("brush %d\n", brush->style); + logger(GUI, Warning, "Unimplemented brush style %d", brush->style); } RESET_FUNCTION(opcode); @@ -3597,7 +3610,7 @@ ui_ellipse(uint8 opcode, break; default: - unimpl("brush %d\n", brush->style); + logger(GUI, Warning, "Unimplemented brush styke %d", brush->style); } RESET_FUNCTION(opcode); @@ -3699,10 +3712,8 @@ ui_draw_text(uint8 font, uint8 flags, uint8 opcode, int mixmode, int x, int y, /* At least two bytes needs to follow */ if (i + 3 > length) { - warning("Skipping short 0xff command:"); - for (j = 0; j < length; j++) - fprintf(stderr, "%02x ", text[j]); - fprintf(stderr, "\n"); + logger(GUI, Warning, + "ui_draw_text(), skipping short 0xff command"); i = length = 0; break; } @@ -3718,10 +3729,8 @@ ui_draw_text(uint8 font, uint8 flags, uint8 opcode, int mixmode, int x, int y, /* At least one byte needs to follow */ if (i + 2 > length) { - warning("Skipping short 0xfe command:"); - for (j = 0; j < length; j++) - fprintf(stderr, "%02x ", text[j]); - fprintf(stderr, "\n"); + logger(GUI, Warning, + "ui_draw_text(), skipping short 0xfe command"); i = length = 0; break; } @@ -4025,7 +4034,8 @@ ui_seamless_create_window(unsigned long id, unsigned long group, unsigned long p if (sw_parent) XSetTransientForHint(g_display, wnd, sw_parent->wnd); else - warning("ui_seamless_create_window: No parent window 0x%lx\n", parent); + logger(GUI, Warning, "ui_seamles_create_window(): no parent window 0x%lx\n", + parent); } if (flags & SEAMLESSRDP_CREATE_MODAL) @@ -4102,7 +4112,8 @@ ui_seamless_destroy_window(unsigned long id, unsigned long flags) sw = sw_get_window_by_id(id); if (!sw) { - warning("ui_seamless_destroy_window: No information for window 0x%lx\n", id); + logger(GUI, Warning, + "ui_seamless_destroy_window(), no information for window 0x%lx", id); return; } @@ -4144,25 +4155,28 @@ ui_seamless_seticon(unsigned long id, const char *format, int width, int height, sw = sw_get_window_by_id(id); if (!sw) { - warning("ui_seamless_seticon: No information for window 0x%lx\n", id); + logger(GUI, Warning, "ui_seamless_seticon(): No information for window 0x%lx", id); return; } if (chunk == 0) { if (sw->icon_size) - warning("ui_seamless_seticon: New icon started before previous completed\n"); + logger(GUI, Warning, + "ui_seamless_seticon(), new icon started before previous completed"); if (strcmp(format, "RGBA") != 0) { - warning("ui_seamless_seticon: Uknown icon format \"%s\"\n", format); + logger(GUI, Warning, "ui_seamless_seticon(), unknown icon format \"%s\"", + format); return; } sw->icon_size = width * height * 4; if (sw->icon_size > 32 * 32 * 4) { - warning("ui_seamless_seticon: Icon too large (%d bytes)\n", sw->icon_size); + logger(GUI, Warning, "ui_seamless_seticon(), icon too large (%d bytes)", + sw->icon_size); sw->icon_size = 0; return; } @@ -4177,8 +4191,9 @@ ui_seamless_seticon(unsigned long id, const char *format, int width, int height, if (chunk_len > (sw->icon_size - sw->icon_offset)) { - warning("ui_seamless_seticon: Too large chunk received (%d bytes > %d bytes)\n", - chunk_len, sw->icon_size - sw->icon_offset); + logger(GUI, Warning, + "ui_seamless_seticon(), too large chunk received (%d bytes > %d bytes)", + chunk_len, sw->icon_size - sw->icon_offset); sw->icon_size = 0; return; } @@ -4205,13 +4220,13 @@ ui_seamless_delicon(unsigned long id, const char *format, int width, int height) sw = sw_get_window_by_id(id); if (!sw) { - warning("ui_seamless_seticon: No information for window 0x%lx\n", id); + logger(GUI, Warning, "ui_seamless_seticon(), no information for window 0x%lx", id); return; } if (strcmp(format, "RGBA") != 0) { - warning("ui_seamless_seticon: Uknown icon format \"%s\"\n", format); + logger(GUI, Warning, "ui_seamless_seticon(), unknown icon format \"%s\"", format); return; } @@ -4230,7 +4245,8 @@ ui_seamless_move_window(unsigned long id, int x, int y, int width, int height, u sw = sw_get_window_by_id(id); if (!sw) { - warning("ui_seamless_move_window: No information for window 0x%lx\n", id); + logger(GUI, Warning, "ui_seamless_move_window(), no information for window 0x%lx", + id); return; } @@ -4276,7 +4292,8 @@ ui_seamless_restack_window(unsigned long id, unsigned long behind, unsigned long sw = sw_get_window_by_id(id); if (!sw) { - warning("ui_seamless_restack_window: No information for window 0x%lx\n", id); + logger(GUI, Warning, + "ui_seamless_restack_window(), no information for window 0x%lx", id); return; } @@ -4287,7 +4304,9 @@ ui_seamless_restack_window(unsigned long id, unsigned long behind, unsigned long sw_behind = sw_get_window_by_id(behind); if (!sw_behind) { - warning("ui_seamless_restack_window: No information for behind window 0x%lx\n", behind); + logger(GUI, Warning, + "ui_seamless_restack_window(), no information for behind window 0x%lx", + behind); return; } @@ -4349,7 +4368,7 @@ ui_seamless_settitle(unsigned long id, const char *title, unsigned long flags) sw = sw_get_window_by_id(id); if (!sw) { - warning("ui_seamless_settitle: No information for window 0x%lx\n", id); + logger(GUI, Warning, "ui_seamless_settitle(), no information for window 0x%lx", id); return; } @@ -4370,7 +4389,7 @@ ui_seamless_setstate(unsigned long id, unsigned int state, unsigned long flags) sw = sw_get_window_by_id(id); if (!sw) { - warning("ui_seamless_setstate: No information for window 0x%lx\n", id); + logger(GUI, Warning, "ui_seamless_setstate(), no information for window 0x%lx", id); return; } @@ -4404,7 +4423,7 @@ ui_seamless_setstate(unsigned long id, unsigned int state, unsigned long flags) XIconifyWindow(g_display, sw->wnd, DefaultScreen(g_display)); break; default: - warning("SeamlessRDP: Invalid state %d\n", state); + logger(GUI, Warning, "ui_seamless_setstate(), invalid state %d", state); break; }