Add lots of protocol debug logging

Signed-off-by: Henrik Andersson <hean01@cendio.com>
Signed-off-by: Karl Mikaelsson <derfian@cendio.se>

mcs.c

@@ -59,7 +59,7 @@ mcs_send_connect_initial(STREAM mcs_data)
 	int datalen = mcs_data->end - mcs_data->data;
 	int length = 9 + 3 * 34 + 4 + datalen;
 	STREAM s;
-
+	logger(Protocol, Debug, "%s()", __func__);
 	s = iso_init(length + 5);
 
 	ber_out_header(s, MCS_CONNECT_INITIAL, length);
@@ -90,7 +90,7 @@ mcs_recv_connect_response(STREAM mcs_data)
 	uint8 result;
 	int length;
 	STREAM s;
-
+	logger(Protocol, Debug, "%s()", __func__);
 	s = iso_recv(NULL);
 	if (s == NULL)
 		return False;
@@ -131,7 +131,7 @@ static void
 mcs_send_edrq(void)
 {
 	STREAM s;
-
+	logger(Protocol, Debug, "%s()", __func__);
 	s = iso_init(5);
 
 	out_uint8(s, (MCS_EDRQ << 2));
@@ -147,7 +147,7 @@ static void
 mcs_send_aurq(void)
 {
 	STREAM s;
-
+	logger(Protocol, Debug, "%s()", __func__);
 	s = iso_init(1);
 
 	out_uint8(s, (MCS_AURQ << 2));
@@ -162,7 +162,7 @@ mcs_recv_aucf(uint16 * mcs_userid)
 {
 	uint8 opcode, result;
 	STREAM s;
-
+	logger(Protocol, Debug, "%s()", __func__);
 	s = iso_recv(NULL);
 	if (s == NULL)
 		return False;
@@ -211,7 +211,7 @@ mcs_recv_cjcf(void)
 {
 	uint8 opcode, result;
 	STREAM s;
-
+	logger(Protocol, Debug, "%s()", __func__);
 	s = iso_recv(NULL);
 	if (s == NULL)
 		return False;
@@ -337,6 +337,7 @@ RD_BOOL
 mcs_connect_start(char *server, char *username, char *domain, char *password,
 		  RD_BOOL reconnect, uint32 * selected_protocol)
 {
+	logger(Protocol, Debug, "%s()", __func__);
 	return iso_connect(server, username, domain, password, reconnect, selected_protocol);
 }
 
@@ -345,6 +346,7 @@ mcs_connect_finalize(STREAM mcs_data)
 {
 	unsigned int i;
 
+	logger(Protocol, Debug, "%s()", __func__);
 	mcs_send_connect_initial(mcs_data);
 	if (!mcs_recv_connect_response(mcs_data))
 		goto error;

rdp.c

@@ -513,6 +513,8 @@ rdp_send_synchronise(void)
 {
 	STREAM s;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	s = rdp_init_data(4);
 
 	out_uint16_le(s, 1);	/* type */
@@ -528,6 +530,8 @@ rdp_send_input(uint32 time, uint16 message_type, uint16 device_flags, uint16 par
 {
 	STREAM s;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	s = rdp_init_data(16);
 
 	out_uint16_le(s, 1);	/* number of events */
@@ -550,6 +554,8 @@ rdp_send_suppress_output_pdu(enum RDP_SUPPRESS_STATUS allowupdates)
 	STREAM s;
 	static enum RDP_SUPPRESS_STATUS current_status = ALLOW_DISPLAY_UPDATES;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	if (current_status == allowupdates)
 		return;
 
@@ -584,6 +590,8 @@ rdp_enum_bmpcache2(void)
 	HASH_KEY keylist[BMPCACHE2_NUM_PSTCELLS];
 	uint32 num_keys, offset, count, flags;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	offset = 0;
 	num_keys = pstcache_enumerate(2, keylist);
 
@@ -626,6 +634,8 @@ rdp_send_fonts(uint16 seq)
 {
 	STREAM s;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	s = rdp_init_data(8);
 
 	out_uint16(s, 0);	/* number of fonts */
@@ -752,6 +762,9 @@ static void
 rdp_out_bmpcache_caps(STREAM s)
 {
 	int Bpp;
+
+	logger(Protocol, Debug, "%s()", __func__);
+
 	out_uint16_le(s, RDP_CAPSET_BMPCACHE);
 	out_uint16_le(s, RDP_CAPLEN_BMPCACHE);
 
@@ -990,6 +1003,8 @@ rdp_send_confirm_active(void)
 		RDP_CAPLEN_LARGE_POINTER +
 		4 /* w2k fix, sessionid */ ;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	if (g_rdp_version >= RDP_V5)
 	{
 		caplen += RDP_CAPLEN_BMPCACHE2;
@@ -1052,6 +1067,8 @@ rdp_process_general_caps(STREAM s)
 {
 	uint16 pad2octetsB;	/* rdp5 flags? */
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	in_uint8s(s, 10);
 	in_uint16_le(s, pad2octetsB);
 
@@ -1065,6 +1082,8 @@ rdp_process_bitmap_caps(STREAM s)
 {
 	uint16 depth;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	in_uint16_le(s, depth);
 	in_uint8s(s, 6);
 
@@ -1101,6 +1120,8 @@ rdp_process_server_caps(STREAM s, uint16 length)
 	uint8 *next, *start;
 	uint16 ncapsets, capset_type, capset_length;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	start = s->p;
 
 	in_uint16_le(s, ncapsets);
@@ -1213,6 +1234,8 @@ process_colour_pointer_common(STREAM s, int bpp)
 void
 process_colour_pointer_pdu(STREAM s)
 {
+	logger(Protocol, Debug, "%s()", __func__);
+
 	process_colour_pointer_common(s, 24);
 }
 
@@ -1221,6 +1244,8 @@ void
 process_new_pointer_pdu(STREAM s)
 {
 	int xor_bpp;
+	logger(Protocol, Debug, "%s()", __func__);
+
 
 	in_uint16_le(s, xor_bpp);
 	process_colour_pointer_common(s, xor_bpp);
@@ -1231,6 +1256,8 @@ void
 process_cached_pointer_pdu(STREAM s)
 {
 	uint16 cache_idx;
+	logger(Protocol, Debug, "%s()", __func__);
+
 
 	in_uint16_le(s, cache_idx);
 	ui_set_cursor(cache_get_cursor(cache_idx));
@@ -1241,6 +1268,8 @@ void
 process_system_pointer_pdu(STREAM s)
 {
 	uint32 system_pointer_type;
+	logger(Protocol, Debug, "%s()", __func__);
+
 	in_uint32_le(s, system_pointer_type);
 
 	set_system_pointer(system_pointer_type);
@@ -1272,6 +1301,8 @@ process_pointer_pdu(STREAM s)
 	uint16 message_type;
 	uint16 x, y;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	in_uint16_le(s, message_type);
 	in_uint8s(s, 2);	/* pad */
 
@@ -1316,6 +1347,8 @@ process_bitmap_updates(STREAM s)
 	uint8 *data, *bmpdata;
 	int i;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	in_uint16_le(s, num_updates);
 
 	for (i = 0; i < num_updates; i++)
@@ -1422,6 +1455,8 @@ process_update_pdu(STREAM s)
 	switch (update_type)
 	{
 		case RDP_UPDATE_ORDERS:
+			logger(Protocol, Debug, "%s(), RDP_UPDATE_ORDERS", __func__);
+
 			in_uint8s(s, 2);	/* pad */
 			in_uint16_le(s, count);
 			in_uint8s(s, 2);	/* pad */
@@ -1429,14 +1464,17 @@ process_update_pdu(STREAM s)
 			break;
 
 		case RDP_UPDATE_BITMAP:
+			logger(Protocol, Debug, "%s(), RDP_UPDATE_BITMAP", __func__);
 			process_bitmap_updates(s);
 			break;
 
 		case RDP_UPDATE_PALETTE:
+			logger(Protocol, Debug, "%s(), RDP_UPDATE_PALETTE", __func__);
 			process_palette(s);
 			break;
 
 		case RDP_UPDATE_SYNCHRONIZE:
+			logger(Protocol, Debug, "%s(), RDP_UPDATE_SYNCHRONIZE", __func__);
 			break;
 
 		default:
@@ -1455,6 +1493,8 @@ process_ts_logon_info_extended(STREAM s)
 	uint32 len;
 	uint32 version;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	in_uint8s(s, 2);	/* Length */
 	in_uint32_le(s, fieldspresent);
 	if (fieldspresent & LOGON_EX_AUTORECONNECTCOOKIE)
@@ -1626,6 +1666,8 @@ process_redirect_pdu(STREAM s, RD_BOOL enhanced_redirect /*, uint32 * ext_disc_r
 	uint32 len;
 	uint16 redirect_identifier;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	/* reset any previous redirection information */
 	g_redirect = True;
 	free(g_redirect_server);
@@ -1900,6 +1942,7 @@ rdp_connect(char *server, uint32 flags, char *domain, char *password,
 void
 rdp_reset_state(void)
 {
+	logger(Protocol, Debug, "%s()", __func__);
 	g_next_packet = NULL;	/* reset the packet information */
 	g_rdp_shareid = 0;
 	g_exit_mainloop = False;
@@ -1910,5 +1953,6 @@ rdp_reset_state(void)
 void
 rdp_disconnect(void)
 {
+	logger(Protocol, Debug, "%s()", __func__);
 	sec_disconnect();
 }

secure.c

@@ -399,6 +399,8 @@ sec_out_mcs_connect_initial_pdu(STREAM s, uint32 selected_protocol)
 	uint16 colorsupport = RNS_UD_24BPP_SUPPORT | RNS_UD_16BPP_SUPPORT | RNS_UD_32BPP_SUPPORT;
 	uint32 physwidth, physheight, desktopscale, devicescale;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	if (g_rdp_version >= RDP_V5)
 		rdpversion = RDP_50;
 
@@ -571,6 +573,8 @@ sec_parse_crypt_info(STREAM s, uint32 * rc4_key_size,
 	uint16 tag, length;
 	uint8 *next_tag, *end;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	in_uint32_le(s, *rc4_key_size);	/* 1 = 40-bit, 2 = 128-bit */
 	in_uint32_le(s, crypt_level);	/* 1 = low, 2 = medium, 3 = high */
 	if (crypt_level == 0)
@@ -755,6 +759,8 @@ sec_process_crypt_info(STREAM s)
 	uint8 exponent[SEC_EXPONENT_SIZE];
 	uint32 rc4_key_size;
 
+	logger(Protocol, Debug, "%s()", __func__);
+
 	memset(modulus, 0, sizeof(modulus));
 	memset(exponent, 0, sizeof(exponent));
 	if (!sec_parse_crypt_info(s, &rc4_key_size, &server_random, modulus, exponent))
@@ -795,6 +801,7 @@ sec_process_mcs_data(STREAM s)
 	in_uint8(s, len);
 	if (len & 0x80)
 		in_uint8(s, len);
+	logger(Protocol, Debug, "%s()", __func__);
 
 	while (s->p < s->end)
 	{
@@ -809,14 +816,17 @@ sec_process_mcs_data(STREAM s)
 		switch (tag)
 		{
 			case SEC_TAG_SRV_INFO:
+				logger(Protocol, Debug, "%s(), SEC_TAG_SRV_INFO", __func__);
 				sec_process_srv_info(s);
 				break;
 
 			case SEC_TAG_SRV_CRYPT:
+				logger(Protocol, Debug, "%s(), SEC_TAG_SRV_CRYPT", __func__);
 				sec_process_crypt_info(s);
 				break;
 
 			case SEC_TAG_SRV_CHANNELS:
+				logger(Protocol, Debug, "%s(), SEC_TAG_SRV_CHANNELS", __func__);
 				/* FIXME: We should parse this information and
 				   use it to map RDP5 channels to MCS 
 				   channels */