gdb_server: Log both incoming and outgoing GDB packets

- Made sure that also outgoing GDB packets are logged,
  not only the incoming ones.

- Improved the treatment of non-printable characters
  in the packets to make it more robust.

Prior to this change:

- Outgoing packets were not printed unless OpenOCD was
  re-compiled with _DEBUG_GDB_IO_.
- Non-prinable characters were only treated in incoming
  'X' packets.

After this change:

- Both incoming and outgoing GDB packets are logged
  on debug_level >= 3, so that both directions of the
  GDB channel are visible.
- Non-printable characters are checked for in every packet
  so that hey do not interfere with the terminal.

Change-Id: I0613e57ae5059b3279b0abcb71276cf5719a8699
Signed-off-by: Jan Matyas <matyas@codasip.com>
Reviewed-on: http://openocd.zylin.com/6269
Tested-by: jenkins
Reviewed-by: Antonio Borneo <borneo.antonio@gmail.com>

src/helper/log.c

@@ -518,3 +518,16 @@ void log_socket_error(const char *socket_desc)
 	LOG_ERROR("Error on socket '%s': errno==%d, message: %s.", socket_desc, error_code, strerror(error_code));
 #endif
 }
+
+/**
+ * Find the first non-printable character in the char buffer, return a pointer to it.
+ * If no such character exists, return NULL.
+ */
+char *find_nonprint_char(char *buf, unsigned buf_len)
+{
+	for (unsigned int i = 0; i < buf_len; i++) {
+		if (!isprint(buf[i]))
+			return buf + i;
+	}
+	return NULL;
+}

src/helper/log.h

@@ -100,6 +100,8 @@ char *alloc_vprintf(const char *fmt, va_list ap);
 char *alloc_printf(const char *fmt, ...)
 	__attribute__ ((format (PRINTF_ATTRIBUTE_FORMAT, 1, 2)));
 
+char *find_nonprint_char(char *buf, unsigned buf_len);
+
 extern int debug_level;
 
 /* Avoid fn call and building parameter list if we're not outputting the information.

src/server/gdb_server.c

@@ -357,14 +357,50 @@ static int gdb_write(struct connection *connection, void *data, int len)
 	return ERROR_SERVER_REMOTE_CLOSED;
 }
 
+static void gdb_log_incoming_packet(char *packet)
+{
+	if (!LOG_LEVEL_IS(LOG_LVL_DEBUG))
+		return;
+
+	/* Avoid dumping non-printable characters to the terminal */
+	const unsigned packet_len = strlen(packet);
+	const char *nonprint = find_nonprint_char(packet, packet_len);
+	if (nonprint) {
+		/* Does packet at least have a prefix that is printable?
+		 * Look within the first 50 chars of the packet. */
+		const char *colon = memchr(packet, ':', MIN(50, packet_len));
+		const bool packet_has_prefix = (colon != NULL);
+		const bool packet_prefix_printable = (packet_has_prefix && nonprint > colon);
+
+		if (packet_prefix_printable) {
+			const unsigned int prefix_len = colon - packet + 1;  /* + 1 to include the ':' */
+			const unsigned int payload_len = packet_len - prefix_len;
+			LOG_DEBUG("received packet: %.*s<binary-data-%u-bytes>", prefix_len, packet, payload_len);
+		} else {
+			LOG_DEBUG("received packet: <binary-data-%u-bytes>", packet_len);
+		}
+	} else {
+		/* All chars printable, dump the packet as is */
+		LOG_DEBUG("received packet: %s", packet);
+	}
+}
+
+static void gdb_log_outgoing_packet(char *packet_buf, unsigned int packet_len, unsigned char checksum)
+{
+	if (!LOG_LEVEL_IS(LOG_LVL_DEBUG))
+		return;
+
+	if (find_nonprint_char(packet_buf, packet_len))
+		LOG_DEBUG("sending packet: $<binary-data-%u-bytes>#%2.2x", packet_len, checksum);
+	else
+		LOG_DEBUG("sending packet: $%.*s#%2.2x'", packet_len, packet_buf, checksum);
+}
+
 static int gdb_put_packet_inner(struct connection *connection,
 		char *buffer, int len)
 {
 	int i;
 	unsigned char my_checksum = 0;
-#ifdef _DEBUG_GDB_IO_
-	char *debug_buffer;
-#endif
 	int reply;
 	int retval;
 	struct gdb_connection *gdb_con = connection->priv;
@@ -400,11 +436,7 @@ static int gdb_put_packet_inner(struct connection *connection,
 #endif
 
 	while (1) {
-#ifdef _DEBUG_GDB_IO_
-		debug_buffer = strndup(buffer, len);
-		LOG_DEBUG("sending packet '$%s#%2.2x'", debug_buffer, my_checksum);
-		free(debug_buffer);
-#endif
+		gdb_log_outgoing_packet(buffer, len, my_checksum);
 
 		char local_buffer[1024];
 		local_buffer[0] = '$';
@@ -3259,18 +3291,7 @@ static int gdb_input_inner(struct connection *connection)
 		/* terminate with zero */
 		gdb_packet_buffer[packet_size] = '\0';
 
-		if (LOG_LEVEL_IS(LOG_LVL_DEBUG)) {
-			if (packet[0] == 'X') {
-				/* binary packets spew junk into the debug log stream */
-				char buf[50];
-				int x;
-				for (x = 0; (x < 49) && (packet[x] != ':'); x++)
-					buf[x] = packet[x];
-				buf[x] = 0;
-				LOG_DEBUG("received packet: '%s:<binary-data>'", buf);
-			} else
-				LOG_DEBUG("received packet: '%s'", packet);
-		}
+		gdb_log_incoming_packet(gdb_packet_buffer);
 
 		if (packet_size > 0) {
 			retval = ERROR_OK;