adb: improve debug traces readability.

This patch makes the traces easier to read. For example transports are
displayed by name/serial instead of their hex address.

Change-Id: I7e8df44ddbec19754d63d989bd56485998b4627b

2 files changed, 124 insertions, 94 deletions

diff --git a/adb/adb.c b/adb/adb.c
index 0da7218..679b086 100644
--- a/adb/adb.c
+++ b/adb/adb.c
@@ -875,7 +875,7 @@ int adb_main(int is_daemon, int server_port)
             // don't run as root if ro.secure is set...
             secure = 1;
 
-            // ... except we allow running as root in userdebug builds if the 
+            // ... except we allow running as root in userdebug builds if the
             // service.adb.root property has been set by the "adb root" command
             property_get("ro.debuggable", value, "");
             if (strcmp(value, "1") == 0) {
@@ -1266,8 +1266,8 @@ int recovery_mode = 0;
 
 int main(int argc, char **argv)
 {
-    adb_trace_init();
 #if ADB_HOST
+    adb_trace_init();
     adb_sysdeps_init();
     return adb_commandline(argc - 1, argv + 1);
 #else
diff --git a/adb/transport.c b/adb/transport.c
index 62bdfdb..2baf340 100644
--- a/adb/transport.c
+++ b/adb/transport.c
@@ -79,7 +79,7 @@ run_transport_disconnects(atransport*  t)
 {
     adisconnect*  dis = t->disconnects.next;
 
-    D("run_transport_disconnects: %p (%s)\n", t, t->serial ? t->serial : "unknown" );
+    D("%s: run_transport_disconnects\n", t->serial);
     while (dis != &t->disconnects) {
         adisconnect*  next = dis->next;
         dis->func( dis->opaque, t );
@@ -87,75 +87,91 @@ run_transport_disconnects(atransport*  t)
     }
 }
 
+#if ADB_TRACE
+static void
+dump_packet(const char* name, const char* func, apacket* p)
+{
+    unsigned  command = p->msg.command;
+    int       len     = p->msg.data_length;
+    char      cmd[9];
+    char      arg0[12], arg1[12];
+    int       n;
+
+    for (n = 0; n < 4; n++) {
+        int  b = (command >> (n*8)) & 255;
+        if (b < 32 || b >= 127)
+            break;
+        cmd[n] = (char)b;
+    }
+    if (n == 4) {
+        cmd[4] = 0;
+    } else {
+        /* There is some non-ASCII name in the command, so dump
+            * the hexadecimal value instead */
+        snprintf(cmd, sizeof cmd, "%08x", command);
+    }
+
+    if (p->msg.arg0 < 256U)
+        snprintf(arg0, sizeof arg0, "%d", p->msg.arg0);
+    else
+        snprintf(arg0, sizeof arg0, "0x%x", p->msg.arg0);
+
+    if (p->msg.arg1 < 256U)
+        snprintf(arg1, sizeof arg1, "%d", p->msg.arg1);
+    else
+        snprintf(arg1, sizeof arg1, "0x%x", p->msg.arg1);
+
+    D("%s: %s: [%s] arg0=%s arg1=%s (len=%d) ",
+        name, func, cmd, arg0, arg1, len);
+    dump_hex(p->data, len);
+}
+#endif /* ADB_TRACE */
+
 static int
-read_packet(int  fd, apacket** ppacket)
+read_packet(int  fd, const char* name, apacket** ppacket)
 {
     char *p = (char*)ppacket;  /* really read a packet address */
     int   r;
     int   len = sizeof(*ppacket);
+    char  buff[8];
+    if (!name) {
+        snprintf(buff, sizeof buff, "fd=%d", fd);
+        name = buff;
+    }
     while(len > 0) {
         r = adb_read(fd, p, len);
         if(r > 0) {
             len -= r;
             p   += r;
         } else {
-            D("read_packet: %d error %d %d\n", fd, r, errno);
+            D("%s: read_packet (fd=%d), error ret=%d errno=%d: %s\n", name, fd, r, errno, strerror(errno));
             if((r < 0) && (errno == EINTR)) continue;
             return -1;
         }
     }
 
 #if ADB_TRACE
-    if (ADB_TRACING)
-    {
-        unsigned  command = (*ppacket)->msg.command;
-        int       len     = (*ppacket)->msg.data_length;
-        char      cmd[5];
-        int       n;
-
-        for (n = 0; n < 4; n++) {
-            int  b = (command >> (n*8)) & 255;
-            if (b >= 32 && b < 127)
-                cmd[n] = (char)b;
-            else
-                cmd[n] = '.';
-        }
-        cmd[4] = 0;
-
-        D("read_packet: %d ok: [%08x %s] %08x %08x (%d) ",
-          fd, command, cmd, (*ppacket)->msg.arg0, (*ppacket)->msg.arg1, len);
-        dump_hex((*ppacket)->data, len);
+    if (ADB_TRACING) {
+        dump_packet(name, "from remote", *ppacket);
     }
 #endif
     return 0;
 }
 
 static int
-write_packet(int  fd, apacket** ppacket)
+write_packet(int  fd, const char* name, apacket** ppacket)
 {
     char *p = (char*) ppacket;  /* we really write the packet address */
     int r, len = sizeof(ppacket);
+    char buff[8];
+    if (!name) {
+        snprintf(buff, sizeof buff, "fd=%d", fd);
+        name = buff;
+    }
 
 #if ADB_TRACE
-    if (ADB_TRACING)
-    {
-        unsigned  command = (*ppacket)->msg.command;
-        int       len     = (*ppacket)->msg.data_length;
-        char      cmd[5];
-        int       n;
-
-        for (n = 0; n < 4; n++) {
-            int  b = (command >> (n*8)) & 255;
-            if (b >= 32 && b < 127)
-                cmd[n] = (char)b;
-            else
-                cmd[n] = '.';
-        }
-        cmd[4] = 0;
-
-        D("write_packet: %d [%08x %s] %08x %08x (%d) ",
-          fd, command, cmd, (*ppacket)->msg.arg0, (*ppacket)->msg.arg1, len);
-        dump_hex((*ppacket)->data, len);
+    if (ADB_TRACING) {
+        dump_packet(name, "to remote", *ppacket);
     }
 #endif
     len = sizeof(ppacket);
@@ -165,7 +181,7 @@ write_packet(int  fd, apacket** ppacket)
             len -= r;
             p += r;
         } else {
-            D("write_packet: %d error %d %d\n", fd, r, errno);
+            D("%s: write_packet (fd=%d) error ret=%d errno=%d: %s\n", name, fd, r, errno, strerror(errno));
             if((r < 0) && (errno == EINTR)) continue;
             return -1;
         }
@@ -175,10 +191,11 @@ write_packet(int  fd, apacket** ppacket)
 
 static void transport_socket_events(int fd, unsigned events, void *_t)
 {
+    atransport *t = _t;
     if(events & FDE_READ){
         apacket *p = 0;
-        if(read_packet(fd, &p)){
-            D("failed to read packet from transport socket on fd %d\n", fd);
+        if(read_packet(fd, t->serial, &p)){
+            D("%s: failed to read packet from transport socket on fd %d\n", t->serial, fd);
         } else {
             handle_packet(p, (atransport *) _t);
         }
@@ -208,7 +225,7 @@ void send_packet(apacket *p, atransport *t)
         D("Transport is null \n");
     }
 
-    if(write_packet(t->transport_socket, &p)){
+    if(write_packet(t->transport_socket, t->serial, &p)){
         fatal_errno("cannot enqueue packet on transport socket");
     }
 }
@@ -231,52 +248,51 @@ static void *output_thread(void *_t)
     atransport *t = _t;
     apacket *p;
 
-    D("from_remote: starting thread for transport %p, on fd %d\n", t, t->fd );
-
-    D("from_remote: transport %p SYNC online (%d)\n", t, t->sync_token + 1);
+    D("%s: starting transport output thread on fd %d, SYNC online (%d)\n",
+       t->serial, t->fd, t->sync_token + 1);
     p = get_apacket();
     p->msg.command = A_SYNC;
     p->msg.arg0 = 1;
     p->msg.arg1 = ++(t->sync_token);
     p->msg.magic = A_SYNC ^ 0xffffffff;
-    if(write_packet(t->fd, &p)) {
+    if(write_packet(t->fd, t->serial, &p)) {
         put_apacket(p);
-        D("from_remote: failed to write SYNC apacket to transport %p", t);
+        D("%s: failed to write SYNC packet\n", t->serial);
         goto oops;
     }
 
-    D("from_remote: data pump  for transport %p\n", t);
+    D("%s: data pump started\n", t->serial);
     for(;;) {
         p = get_apacket();
 
         if(t->read_from_remote(p, t) == 0){
-            D("from_remote: received remote packet, sending to transport %p\n",
-              t);
-            if(write_packet(t->fd, &p)){
+            D("%s: received remote packet, sending to transport\n",
+              t->serial);
+            if(write_packet(t->fd, t->serial, &p)){
                 put_apacket(p);
-                D("from_remote: failed to write apacket to transport %p", t);
+                D("%s: failed to write apacket to transport\n", t->serial);
                 goto oops;
             }
         } else {
-            D("from_remote: remote read failed for transport %p\n", p);
+            D("%s: remote read failed for transport\n", t->serial);
             put_apacket(p);
             break;
         }
     }
 
-    D("from_remote: SYNC offline for transport %p\n", t);
+    D("%s: SYNC offline for transport\n", t->serial);
     p = get_apacket();
     p->msg.command = A_SYNC;
     p->msg.arg0 = 0;
     p->msg.arg1 = 0;
     p->msg.magic = A_SYNC ^ 0xffffffff;
-    if(write_packet(t->fd, &p)) {
+    if(write_packet(t->fd, t->serial, &p)) {
         put_apacket(p);
-        D("from_remote: failed to write SYNC apacket to transport %p", t);
+        D("%s: failed to write SYNC apacket to transport", t->serial);
     }
 
 oops:
-    D("from_remote: thread is exiting for transport %p\n", t);
+    D("%s: transport output thread is exiting\n", t->serial);
     kick_transport(t);
     transport_unref(t);
     return 0;
@@ -288,35 +304,35 @@ static void *input_thread(void *_t)
     apacket *p;
     int active = 0;
 
-    D("to_remote: starting input_thread for %p, reading from fd %d\n",
-       t, t->fd);
+    D("%s: starting transport input thread, reading from fd %d\n",
+       t->serial, t->fd);
 
     for(;;){
-        if(read_packet(t->fd, &p)) {
-            D("to_remote: failed to read apacket from transport %p on fd %d\n", 
-               t, t->fd );
+        if(read_packet(t->fd, t->serial, &p)) {
+            D("%s: failed to read apacket from transport on fd %d\n",
+               t->serial, t->fd );
             break;
         }
         if(p->msg.command == A_SYNC){
             if(p->msg.arg0 == 0) {
-                D("to_remote: transport %p SYNC offline\n", t);
+                D("%s: transport SYNC offline\n", t->serial);
                 put_apacket(p);
                 break;
             } else {
                 if(p->msg.arg1 == t->sync_token) {
-                    D("to_remote: transport %p SYNC online\n", t);
+                    D("%s: transport SYNC online\n", t->serial);
                     active = 1;
                 } else {
-                    D("to_remote: trandport %p ignoring SYNC %d != %d\n",
-                      t, p->msg.arg1, t->sync_token);
+                    D("%s: transport ignoring SYNC %d != %d\n",
+                      t->serial, p->msg.arg1, t->sync_token);
                 }
             }
         } else {
             if(active) {
-                D("to_remote: transport %p got packet, sending to remote\n", t);
+                D("%s: transport got packet, sending to remote\n", t->serial);
                 t->write_to_remote(p, t);
             } else {
-                D("to_remote: transport %p ignoring packet while offline\n", t);
+                D("%s: transport ignoring packet while offline\n", t->serial);
             }
         }
 
@@ -327,7 +343,7 @@ static void *input_thread(void *_t)
     // while a client socket is still active.
     close_all_sockets(t);
 
-    D("to_remote: thread is exiting for transport %p, fd %d\n", t, t->fd);
+    D("%s: transport input thread is exiting, fd %d\n", t->serial, t->fd);
     kick_transport(t);
     transport_unref(t);
     return 0;
@@ -508,7 +524,7 @@ transport_read_action(int  fd, struct tmsg*  m)
             p   += r;
         } else {
             if((r < 0) && (errno == EINTR)) continue;
-            D("transport_read_action: on fd %d, error %d: %s\n", 
+            D("transport_read_action: on fd %d, error %d: %s\n",
               fd, errno, strerror(errno));
             return -1;
         }
@@ -530,7 +546,7 @@ transport_write_action(int  fd, struct tmsg*  m)
             p   += r;
         } else {
             if((r < 0) && (errno == EINTR)) continue;
-            D("transport_write_action: on fd %d, error %d: %s\n", 
+            D("transport_write_action: on fd %d, error %d: %s\n",
               fd, errno, strerror(errno));
             return -1;
         }
@@ -557,7 +573,7 @@ static void transport_registration_func(int _fd, unsigned ev, void *data)
     t = m.transport;
 
     if(m.action == 0){
-        D("transport: %p removing and free'ing %d\n", t, t->transport_socket);
+        D("transport: %s removing and free'ing %d\n", t->serial, t->transport_socket);
 
             /* IMPORTANT: the remove closes one half of the
             ** socket pair.  The close closes the other half.
@@ -593,12 +609,11 @@ static void transport_registration_func(int _fd, unsigned ev, void *data)
             fatal_errno("cannot open transport socketpair");
         }
 
-        D("transport: %p (%d,%d) starting\n", t, s[0], s[1]);
+        D("transport: %s (%d,%d) starting\n", t->serial, s[0], s[1]);
 
         t->transport_socket = s[0];
         t->fd = s[1];
 
-        D("transport: %p install %d\n", t, t->transport_socket );
         fdevent_install(&(t->transport_fde),
                         t->transport_socket,
                         transport_socket_events,
@@ -653,7 +668,7 @@ static void register_transport(atransport *transport)
     tmsg m;
     m.transport = transport;
     m.action = 1;
-    D("transport: %p registered\n", transport);
+    D("transport: %s registered\n", transport->serial);
     if(transport_write_action(transport_registration_send, &m)) {
         fatal_errno("cannot write transport registration socket\n");
     }
@@ -664,7 +679,7 @@ static void remove_transport(atransport *transport)
     tmsg m;
     m.transport = transport;
     m.action = 0;
-    D("transport: %p removed\n", transport);
+    D("transport: %s removed\n", transport->serial);
     if(transport_write_action(transport_registration_send, &m)) {
         fatal_errno("cannot write transport registration socket\n");
     }
@@ -674,15 +689,16 @@ static void remove_transport(atransport *transport)
 static void transport_unref_locked(atransport *t)
 {
     t->ref_count--;
-    D("transport: %p R- (ref=%d)\n", t, t->ref_count);
     if (t->ref_count == 0) {
-        D("transport: %p kicking and closing\n", t);
+        D("transport: %s unref (kicking and closing)\n", t->serial);
         if (!t->kicked) {
             t->kicked = 1;
             t->kick(t);
         }
         t->close(t);
         remove_transport(t);
+    } else {
+        D("transport: %s unref (count=%d)\n", t->serial, t->ref_count);
     }
 }
 
@@ -857,7 +873,13 @@ void close_usb_devices()
 void register_socket_transport(int s, const char *serial, int port, int local)
 {
     atransport *t = calloc(1, sizeof(atransport));
-    D("transport: %p init'ing for socket %d, on port %d\n", t, s, port);
+    char buff[32];
+
+    if (!serial) {
+        snprintf(buff, sizeof buff, "T-%p", t);
+        serial = buff;
+    }
+    D("transport: %s init'ing for socket %d, on port %d\n", serial, s, port);
     if ( init_socket_transport(t, s, port, local) < 0 ) {
         adb_close(s);
         free(t);
@@ -961,21 +983,26 @@ int readx(int fd, void *ptr, size_t len)
 #if ADB_TRACE
     int  len0 = len;
 #endif
-    D("readx: %d %p %d\n", fd, ptr, (int)len);
+    D("readx: fd=%d wanted=%d\n", fd, (int)len);
     while(len > 0) {
         r = adb_read(fd, p, len);
         if(r > 0) {
             len -= r;
             p += r;
         } else {
-            D("readx: %d %d %s\n", fd, r, strerror(errno));
-            if((r < 0) && (errno == EINTR)) continue;
+            if (r < 0) {
+                D("readx: fd=%d error %d: %s\n", fd, errno, strerror(errno));
+                if (errno == EINTR)
+                    continue;
+            } else {
+                D("readx: fd=%d disconnected\n", fd);
+            }
             return -1;
         }
     }
 
 #if ADB_TRACE
-    D("readx: %d ok: ", fd);
+    D("readx: fd=%d wanted=%d got=%d\n", fd, len0, len0 - len);
     dump_hex( ptr, len0 );
 #endif
     return 0;
@@ -987,7 +1014,7 @@ int writex(int fd, const void *ptr, size_t len)
     int r;
 
 #if ADB_TRACE
-    D("writex: %d %p %d: ", fd, ptr, (int)len);
+    D("writex: fd=%d len=%d: ", fd, (int)len);
     dump_hex( ptr, len );
 #endif
     while(len > 0) {
@@ -996,13 +1023,16 @@ int writex(int fd, const void *ptr, size_t len)
             len -= r;
             p += r;
         } else {
-            D("writex: %d %d %s\n", fd, r, strerror(errno));
-            if((r < 0) && (errno == EINTR)) continue;
+            if (r < 0) {
+                D("writex: fd=%d error %d: %s\n", fd, errno, strerror(errno));
+                if (errno == EINTR)
+                    continue;
+            } else {
+                D("writex: fd=%d disconnected\n", fd);
+            }
             return -1;
         }
     }
-
-    D("writex: %d ok\n", fd);
     return 0;
 }