Fix adb hang when subprocess dies early.

* Handling of the subprocess and its FD.
  This fixes http://b/3400254 "Many bugreports getting hung at the end in monkey"
  -  Start up a service thread that waits on the subprocess to terminate,
then closes the FD associated with it.
  -  Have the event handler select() with a timeout so that it can
  detect the closed FD. Select() with no timeout does not return when an FD is closed.
  - Have the event handler force a read on the closed FD to trigger the close sequence.
  - Migrate the "shell:blabla" handling to "#if !ADB_HOST" sections.
* Fix the race around OOM adjusting.
  - Do it in the child before exec() instead of the in the parent as the
   child could already have started or not (no /proc/pid/... yet).
* Allow for multi-threaded D() invocations to not clobber each other.
  - Allow locks across object files.
  - Add lock within D()
* Add some missing close(fd) calls
  - Match similar existing practices near dup2()
* Add extra D() invocations related to FD handling.
* Warn about using debugging as stderr/stdout is used for protocol.

Change-Id: Ie5c4a5e6bfbe3f22201adf5f9a205d32e069bf9d
Signed-off-by: JP Abgrall <jpa@google.com>

12 files changed, 314 insertions, 80 deletions

diff --git a/adb/adb.c b/adb/adb.c
index f5e6e0c05..6e2c0a922 100644
--- a/adb/adb.c
+++ b/adb/adb.c
@@ -36,6 +36,9 @@
 #include "usb_vendors.h"
 #endif
 
+#if ADB_TRACE
+ADB_MUTEX_DEFINE( D_lock );
+#endif
 
 int HOST = 0;
 
@@ -591,14 +594,6 @@ nomem:
     return 0;
 }
 
-#ifdef HAVE_FORKEXEC
-static void sigchld_handler(int n)
-{
-    int status;
-    while(waitpid(-1, &status, WNOHANG) > 0) ;
-}
-#endif
-
 #ifdef HAVE_WIN32_PROC
 static BOOL WINAPI ctrlc_handler(DWORD type)
 {
@@ -641,6 +636,7 @@ void start_logging(void)
 
     fd = unix_open("/dev/null", O_RDONLY);
     dup2(fd, 0);
+    adb_close(fd);
 
     fd = unix_open("/tmp/adb.log", O_WRONLY | O_CREAT | O_APPEND, 0640);
     if(fd < 0) {
@@ -648,6 +644,8 @@ void start_logging(void)
     }
     dup2(fd, 1);
     dup2(fd, 2);
+    adb_close(fd);
+
     fprintf(stderr,"--- adb starting (pid %d) ---\n", getpid());
 #endif
 }
@@ -792,6 +790,7 @@ int launch_server(int server_port)
         // we use stderr instead of stdout due to stdout's buffering behavior.
         adb_close(fd[0]);
         dup2(fd[1], STDERR_FILENO);
+        dup2(fd[1], STDOUT_FILENO);
         adb_close(fd[1]);
 
         // child process
@@ -848,7 +847,7 @@ int adb_main(int is_daemon, int server_port)
 #ifdef HAVE_WIN32_PROC
     SetConsoleCtrlHandler( ctrlc_handler, TRUE );
 #elif defined(HAVE_FORKEXEC)
-    signal(SIGCHLD, sigchld_handler);
+    // Let the service subproc creator handle its children.
     signal(SIGPIPE, SIG_IGN);
 #endif
 
@@ -957,7 +956,9 @@ int adb_main(int is_daemon, int server_port)
         // listen on default port
         local_init(DEFAULT_ADB_LOCAL_TRANSPORT_PORT);
     }
+    D("adb_main(): pre init_jdwp()\n");
     init_jdwp();
+    D("adb_main(): post init_jdwp()\n");
 #endif
 
     if (is_daemon)
@@ -971,6 +972,7 @@ int adb_main(int is_daemon, int server_port)
 #endif
         start_logging();
     }
+    D("Event loop starting\n");
 
     fdevent_loop();
 
@@ -1271,6 +1273,7 @@ int main(int argc, char **argv)
 #if ADB_HOST
     adb_trace_init();
     adb_sysdeps_init();
+    D("Handling commandline()\n");
     return adb_commandline(argc - 1, argv + 1);
 #else
     if((argc > 1) && (!strcmp(argv[1],"recovery"))) {
@@ -1279,6 +1282,7 @@ int main(int argc, char **argv)
     }
 
     start_device_log();
+    D("Handling main()\n");
     return adb_main(0, DEFAULT_ADB_PORT);
 #endif
 }
diff --git a/adb/adb.h b/adb/adb.h
index 0aa98d3db..7cbf3d33b 100644
--- a/adb/adb.h
+++ b/adb/adb.h
@@ -123,7 +123,7 @@ struct asocket {
         /* socket-type-specific extradata */
     void *extra;
 
-    	/* A socket is bound to atransport */
+        /* A socket is bound to atransport */
     atransport *transport;
 };
 
@@ -344,20 +344,50 @@ typedef enum {
 
 #if ADB_TRACE
 
-  int     adb_trace_mask;
+// TODO(jpa): remove this after fixing fprintf() multithreading issue {
+// Can't include sysdeps.h, because framebuffer_service.c wants a different
+// close() than what sysdeps overrides when linking adbd.
 
+// Assume Linux.
+#ifndef _ADB_SYSDEPS_H
+#include <pthread.h>
+typedef  pthread_mutex_t          adb_mutex_t;
+#define  ADB_MUTEX(x)   extern adb_mutex_t  x;
+#include "mutex_list.h"
+#endif
+
+// }
+
+  extern int     adb_trace_mask;
+  extern unsigned char    adb_trace_output_count;
   void    adb_trace_init(void);
 
 #  define ADB_TRACING  ((adb_trace_mask & (1 << TRACE_TAG)) != 0)
 
   /* you must define TRACE_TAG before using this macro */
-  #define  D(...)                                      \
+#  define  D(...)                                      \
+        do {                                           \
+            if (ADB_TRACING) {                         \
+                adb_mutex_lock(&D_lock);               \
+                fprintf(stderr, "%s::%s():",           \
+                    __FILE__, __FUNCTION__);           \
+                fprintf(stderr, __VA_ARGS__ );         \
+                fflush(stderr);                        \
+                adb_mutex_unlock(&D_lock);             \
+           }                                           \
+        } while (0)
+#  define  DR(...)                                     \
         do {                                           \
-            if (ADB_TRACING)                           \
+            if (ADB_TRACING) {                         \
+                adb_mutex_lock(&D_lock);               \
                 fprintf(stderr, __VA_ARGS__ );         \
+                fflush(stderr);                        \
+                adb_mutex_unlock(&D_lock);             \
+           }                                           \
         } while (0)
 #else
 #  define  D(...)          ((void)0)
+#  define  DR(...)         ((void)0)
 #  define  ADB_TRACING     0
 #endif
 
diff --git a/adb/adb_client.c b/adb/adb_client.c
index 882810a95..9a812f0cf 100644
--- a/adb/adb_client.c
+++ b/adb/adb_client.c
@@ -202,6 +202,7 @@ int _adb_connect(const char *service)
         return -1;
     }
 
+    D("_adb_connect: return fd %d\n", fd);
     return fd;
 }
 
@@ -210,6 +211,7 @@ int adb_connect(const char *service)
     // first query the adb server's version
     int fd = _adb_connect("host:version");
 
+    D("adb_connect: service %s\n", service);
     if(fd == -2) {
         fprintf(stdout,"* daemon not running. starting it now on port %d *\n",
                 __adb_server_port);
@@ -266,6 +268,7 @@ int adb_connect(const char *service)
     if(fd == -2) {
         fprintf(stderr,"** daemon still not running");
     }
+    D("adb_connect: return fd %d\n", fd);
 
     return fd;
 error:
diff --git a/adb/commandline.c b/adb/commandline.c
index 5ed1b522b..c897efe03 100644
--- a/adb/commandline.c
+++ b/adb/commandline.c
@@ -218,7 +218,9 @@ static void read_and_dump(int fd)
     int len;
 
     while(fd >= 0) {
+        D("read_and_dump(): pre adb_read(fd=%d)\n", fd);
         len = adb_read(fd, buf, 4096);
+        D("read_and_dump(): post adb_read(fd=%d): len=%d\n", fd, len);
         if(len == 0) {
             break;
         }
@@ -246,7 +248,9 @@ static void *stdin_read_thread(void *x)
 
     for(;;) {
         /* fdi is really the client's stdin, so use read, not adb_read here */
+        D("stdin_read_thread(): pre unix_read(fdi=%d,...)\n", fdi);
         r = unix_read(fdi, buf, 1024);
+        D("stdin_read_thread(): post unix_read(fdi=%d,...)\n", fdi);
         if(r == 0) break;
         if(r < 0) {
             if(errno == EINTR) continue;
@@ -853,6 +857,7 @@ top:
         }
 
         if(argc < 2) {
+            D("starting interactive shell\n");
             r = interactive_shell();
             if (h) {
                 printf("\x1b[0m");
@@ -877,9 +882,12 @@ top:
         }
 
         for(;;) {
+            D("interactive shell loop. buff=%s\n", buf);
             fd = adb_connect(buf);
             if(fd >= 0) {
+                D("about to read_and_dump(fd=%d)\n", fd);
                 read_and_dump(fd);
+                D("read_and_dump() done.\n");
                 adb_close(fd);
                 r = 0;
             } else {
@@ -896,6 +904,7 @@ top:
                     printf("\x1b[0m");
                     fflush(stdout);
                 }
+                D("interactive shell loop. return r=%d\n", r);
                 return r;
             }
         }
diff --git a/adb/fdevent.c b/adb/fdevent.c
index c179b201d..a81b2df0d 100644
--- a/adb/fdevent.c
+++ b/adb/fdevent.c
@@ -2,16 +2,16 @@
 **
 ** Copyright 2006, Brian Swetland <swetland@frotz.net>
 **
-** Licensed under the Apache License, Version 2.0 (the "License"); 
-** you may not use this file except in compliance with the License. 
-** You may obtain a copy of the License at 
+** Licensed under the Apache License, Version 2.0 (the "License");
+** you may not use this file except in compliance with the License.
+** You may obtain a copy of the License at
 **
-**     http://www.apache.org/licenses/LICENSE-2.0 
+**     http://www.apache.org/licenses/LICENSE-2.0
 **
-** Unless required by applicable law or agreed to in writing, software 
-** distributed under the License is distributed on an "AS IS" BASIS, 
-** WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 
-** See the License for the specific language governing permissions and 
+** Unless required by applicable law or agreed to in writing, software
+** distributed under the License is distributed on an "AS IS" BASIS,
+** WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+** See the License for the specific language governing permissions and
 ** limitations under the License.
 */
 
@@ -28,9 +28,12 @@
 
 #include "fdevent.h"
 
-#define TRACE(x...) fprintf(stderr,x)
 
-#define DEBUG 0
+/* !!! Do not enable DEBUG for the adb that will run as the server:
+** both stdout and stderr are used to communicate between the client
+** and server. Any extra output will cause failures.
+*/
+#define DEBUG 0   /* non-0 will break adb server */
 
 static void fatal(const char *fn, const char *fmt, ...)
 {
@@ -45,6 +48,11 @@ static void fatal(const char *fn, const char *fmt, ...)
 #define FATAL(x...) fatal(__FUNCTION__, x)
 
 #if DEBUG
+#define D(...) \
+    do { \
+        fprintf(stderr, "%s::%s():", __FILE__, __FUNCTION__);  \
+        fprintf(stderr, __VA_ARGS__);                          \
+    } while(0)
 static void dump_fde(fdevent *fde, const char *info)
 {
     fprintf(stderr,"FDE #%03d %c%c%c %s\n", fde->fd,
@@ -54,6 +62,7 @@ static void dump_fde(fdevent *fde, const char *info)
             info);
 }
 #else
+#define D(...) ((void)0)
 #define dump_fde(fde, info) do { } while(0)
 #endif
 
@@ -270,7 +279,68 @@ static void fdevent_update(fdevent *fde, unsigned events)
         FD_CLR(fde->fd, &error_fds);
     }
 
-    fde->state = (fde->state & FDE_STATEMASK) | events;    
+    fde->state = (fde->state & FDE_STATEMASK) | events;
+}
+
+#if DEBUG
+static void dump_all_fds(const char *extra_msg)
+{
+int i;
+    fdevent *fde;
+    // per fd: 4 digits (but really: log10(FD_SETSIZE)), 1 staus, 1 blank
+    char msg_buff[FD_SETSIZE*6 + 1], *pb=msg_buff;
+    size_t max_chars = FD_SETSIZE * 6 + 1;
+    int printed_out;
+#define SAFE_SPRINTF(...)                                                    \
+    do {                                                                     \
+        printed_out = snprintf(pb, max_chars, __VA_ARGS__);                  \
+        if (printed_out <= 0) {                                              \
+            D("... snprintf failed.\n");                                     \
+            return;                                                          \
+        }                                                                    \
+        if (max_chars < (unsigned int)printed_out) {                         \
+            D("... snprintf out of space.\n");                               \
+            return;                                                          \
+        }                                                                    \
+        pb += printed_out;                                                   \
+        max_chars -= printed_out;                                            \
+    } while(0)
+
+    for(i = 0; i < select_n; i++) {
+        fde = fd_table[i];
+        SAFE_SPRINTF("%d", i);
+        if(fde == 0) {
+            SAFE_SPRINTF("? ");
+            continue;
+        }
+        if(fcntl(i, F_GETFL, NULL) < 0) {
+            SAFE_SPRINTF("b");
+        }
+        SAFE_SPRINTF(" ");
+    }
+    D("%s fd_table[]->fd = {%s}\n", extra_msg, msg_buff);
+}
+#endif
+
+/* Looks at fd_table[] for bad FDs and sets bit in fds.
+** Returns the number of bad FDs.
+*/
+static int fdevent_fd_check(fd_set *fds)
+{
+    int i, n = 0;
+    fdevent *fde;
+
+    for(i = 0; i < select_n; i++) {
+        fde = fd_table[i];
+        if(fde == 0) continue;
+        if(fcntl(i, F_GETFL, NULL) < 0) {
+            FD_SET(i, fds);
+            n++;
+            fde->state |= FDE_DONT_CLOSE;
+
+        }
+    }
+    return n;
 }
 
 static void fdevent_process()
@@ -279,33 +349,54 @@ static void fdevent_process()
     fdevent *fde;
     unsigned events;
     fd_set rfd, wfd, efd;
+    struct timeval tv = { /*tv_sec=*/5, /*tv_usec=*/0 };
 
     memcpy(&rfd, &read_fds, sizeof(fd_set));
     memcpy(&wfd, &write_fds, sizeof(fd_set));
     memcpy(&efd, &error_fds, sizeof(fd_set));
 
-    n = select(select_n, &rfd, &wfd, &efd, 0);
+    n = select(select_n, &rfd, &wfd, &efd, &tv);
+
+    D("select() returned n=%d, errno=%d\n", n, n<0?errno:0);
+
+#if DEBUG
+    dump_all_fds("post select()");
+#endif
 
     if(n < 0) {
-        if(errno == EINTR) return;
-        perror("select");
-        return;
+        switch(errno) {
+        case EINTR: return;
+        case EBADF:
+            // Can't trust the FD sets after an error.
+            FD_ZERO(&wfd);
+            FD_ZERO(&efd);
+            FD_ZERO(&rfd);
+            break;
+        default:
+            D("Unexpected select() error=%d\n", errno);
+            return;
+        }
+    }
+    if(n <= 0) {
+        // We fake a read, as the rest of the code assumes
+        // that errors will be detected at that point.
+        n = fdevent_fd_check(&rfd);
     }
 
     for(i = 0; (i < select_n) && (n > 0); i++) {
         events = 0;
-        if(FD_ISSET(i, &rfd)) events |= FDE_READ;
-        if(FD_ISSET(i, &wfd)) events |= FDE_WRITE;
-        if(FD_ISSET(i, &efd)) events |= FDE_ERROR;
+        if(FD_ISSET(i, &rfd)) { events |= FDE_READ; n--; }
+        if(FD_ISSET(i, &wfd)) { events |= FDE_WRITE; n--; }
+        if(FD_ISSET(i, &efd)) { events |= FDE_ERROR; n--; }
 
         if(events) {
-            n--;
-
             fde = fd_table[i];
             if(fde == 0) FATAL("missing fde for fd %d\n", i);
 
             fde->events |= events;
 
+            D("got events fde->fd=%d events=%04x, state=%04x\n",
+                fde->fd, fde->events, fde->state);
             if(fde->state & FDE_PENDING) continue;
             fde->state |= FDE_PENDING;
             fdevent_plist_enqueue(fde);
@@ -350,7 +441,7 @@ static void fdevent_unregister(fdevent *fde)
     }
 
     if(fd_table[fde->fd] != fde) {
-        FATAL("fd_table out of sync");
+        FATAL("fd_table out of sync [%d]\n", fde->fd);
     }
 
     fd_table[fde->fd] = 0;
@@ -412,7 +503,7 @@ void fdevent_destroy(fdevent *fde)
     fdevent_remove(fde);
 }
 
-void fdevent_install(fdevent *fde, int fd, fd_func func, void *arg) 
+void fdevent_install(fdevent *fde, int fd, fd_func func, void *arg)
 {
     memset(fde, 0, sizeof(fdevent));
     fde->state = FDE_ACTIVE;
@@ -437,7 +528,7 @@ void fdevent_remove(fdevent *fde)
 
     if(fde->state & FDE_ACTIVE) {
         fdevent_disconnect(fde);
-        dump_fde(fde, "disconnect");    
+        dump_fde(fde, "disconnect");
         fdevent_unregister(fde);
     }
 
@@ -489,9 +580,8 @@ void fdevent_loop()
     fdevent *fde;
 
     for(;;) {
-#if DEBUG
-        fprintf(stderr,"--- ---- waiting for events\n");
-#endif
+        D("--- ---- waiting for events\n");
+
         fdevent_process();
 
         while((fde = fdevent_plist_dequeue())) {
@@ -503,4 +593,3 @@ void fdevent_loop()
         }
     }
 }
-
diff --git a/adb/mutex_list.h b/adb/mutex_list.h
index eebe0dfcb..83f3e4280 100644
--- a/adb/mutex_list.h
+++ b/adb/mutex_list.h
@@ -1,4 +1,6 @@
 /* the list of mutexes used by addb */
+#ifndef __MUTEX_LIST_H
+#define __MUTEX_LIST_H
 #ifndef ADB_MUTEX
 #error ADB_MUTEX not defined when including this file
 #endif
@@ -11,4 +13,14 @@ ADB_MUTEX(local_transports_lock)
 #endif
 ADB_MUTEX(usb_lock)
 
+// Sadly logging to /data/adb/adb-... is not thread safe.
+//  After modifying adb.h::D() to count invocations:
+//   DEBUG(jpa):0:Handling main()
+//   DEBUG(jpa):1:[ usb_init - starting thread ]
+// (Oopsies, no :2:, and matching message is also gone.)
+//   DEBUG(jpa):3:[ usb_thread - opening device ]
+//   DEBUG(jpa):4:jdwp control socket started (10)
+ADB_MUTEX(D_lock)
+
 #undef ADB_MUTEX
+#endif
diff --git a/adb/services.c b/adb/services.c
index c22ce17cc..e2b58fee2 100644
--- a/adb/services.c
+++ b/adb/services.c
@@ -268,15 +268,15 @@ static int create_service_thread(void (*func)(int, void *), void *cookie)
     return s[0];
 }
 
-static int create_subprocess(const char *cmd, const char *arg0, const char *arg1)
+static int create_subprocess(const char *cmd, const char *arg0, const char *arg1, pid_t *pid)
 {
+    D("create_subprocess(cmd=%s, arg0=%s, arg1=%s)\n", cmd, arg0, arg1);
 #ifdef HAVE_WIN32_PROC
-	fprintf(stderr, "error: create_subprocess not implemented on Win32 (%s %s %s)\n", cmd, arg0, arg1);
-	return -1;
+    fprintf(stderr, "error: create_subprocess not implemented on Win32 (%s %s %s)\n", cmd, arg0, arg1);
+    return -1;
 #else /* !HAVE_WIN32_PROC */
     char *devname;
     int ptm;
-    pid_t pid;
 
     ptm = unix_open("/dev/ptmx", O_RDWR); // | O_NOCTTY);
     if(ptm < 0){
@@ -291,19 +291,22 @@ static int create_subprocess(const char *cmd, const char *arg0, const char *arg1
         return -1;
     }
 
-    pid = fork();
-    if(pid < 0) {
+    *pid = fork();
+    if(*pid < 0) {
         printf("- fork failed: %s -\n", strerror(errno));
         return -1;
     }
 
-    if(pid == 0){
+    if(*pid == 0){
         int pts;
 
         setsid();
 
         pts = unix_open(devname, O_RDWR);
-        if(pts < 0) exit(-1);
+        if(pts < 0) {
+            fprintf(stderr, "child failed to open pseudo-term slave: %s\n", devname);
+            exit(-1);
+        }
 
         dup2(pts, 0);
         dup2(pts, 1);
@@ -312,15 +315,10 @@ static int create_subprocess(const char *cmd, const char *arg0, const char *arg1
         adb_close(pts);
         adb_close(ptm);
 
-        execl(cmd, cmd, arg0, arg1, NULL);
-        fprintf(stderr, "- exec '%s' failed: %s (%d) -\n",
-                cmd, strerror(errno), errno);
-        exit(-1);
-    } else {
 #if !ADB_HOST
-        // set child's OOM adjustment to zero
+        // set OOM adjustment to zero
         char text[64];
-        snprintf(text, sizeof text, "/proc/%d/oom_adj", pid);
+        snprintf(text, sizeof text, "/proc/%d/oom_adj", getpid());
         int fd = adb_open(text, O_WRONLY);
         if (fd >= 0) {
             adb_write(fd, "0", 1);
@@ -329,6 +327,17 @@ static int create_subprocess(const char *cmd, const char *arg0, const char *arg1
            D("adb: unable to open %s\n", text);
         }
 #endif
+        execl(cmd, cmd, arg0, arg1, NULL);
+        fprintf(stderr, "- exec '%s' failed: %s (%d) -\n",
+                cmd, strerror(errno), errno);
+        exit(-1);
+    } else {
+#if !ADB_HOST
+        // Don't set child's OOM adjustment to zero.
+        // Let the child do it itself, as sometimes the parent starts
+        // running before the child has a /proc/pid/oom_adj.
+        // """adb: unable to open /proc/644/oom_adj""" seen in some logs.
+#endif
         return ptm;
     }
 #endif /* !HAVE_WIN32_PROC */
@@ -340,6 +349,67 @@ static int create_subprocess(const char *cmd, const char *arg0, const char *arg1
 #define SHELL_COMMAND "/system/bin/sh"
 #endif
 
+#if !ADB_HOST
+static void subproc_waiter_service(int fd, void *cookie)
+{
+    pid_t pid = (pid_t)cookie;
+
+    D("entered. fd=%d of pid=%d\n", fd, pid);
+    for (;;) {
+        int status;
+        pid_t p = waitpid(pid, &status, 0);
+        if (p == pid) {
+            D("fd=%d, post waitpid(pid=%d) status=%04x\n", fd, p, status);
+            if (WIFSIGNALED(status)) {
+                D("*** Killed by signal %d\n", WTERMSIG(status));
+                break;
+            } else if (!WIFEXITED(status)) {
+                D("*** Didn't exit!!. status %d\n", status);
+                break;
+            } else if (WEXITSTATUS(status) >= 0) {
+                D("*** Exit code %d\n", WEXITSTATUS(status));
+                break;
+            }
+         }
+        usleep(100000);  // poll every 0.1 sec
+    }
+    D("closing fd=%d of pid=%d\n", fd, pid);
+    sleep(5);   // Give a chance for the exiting proc to flush.
+    adb_close(fd);
+}
+
+static int create_subproc_thread(const char *name)
+{
+    stinfo *sti;
+    adb_thread_t t;
+    int ret_fd;
+    pid_t pid;
+
+    if(name) {
+        ret_fd = create_subprocess(SHELL_COMMAND, "-c", name, &pid);
+    } else {
+        ret_fd = create_subprocess(SHELL_COMMAND, "-", 0, &pid);
+    }
+    D("create_subprocess() ret_fd=%d pid=%d\n", ret_fd, pid);
+
+    sti = malloc(sizeof(stinfo));
+    if(sti == 0) fatal("cannot allocate stinfo");
+    sti->func = subproc_waiter_service;
+    sti->cookie = (void*)pid;
+    sti->fd = ret_fd;
+
+    if(adb_thread_create( &t, service_bootstrap_func, sti)){
+        free(sti);
+        adb_close(ret_fd);
+        printf("cannot create service thread\n");
+        return -1;
+    }
+
+    D("service thread started, fd=%d pid=%d\n",ret_fd, pid);
+    return ret_fd;
+}
+#endif
+
 int service_to_fd(const char *name)
 {
     int ret = -1;
@@ -390,14 +460,12 @@ int service_to_fd(const char *name)
         ret = create_jdwp_connection_fd(atoi(name+5));
     } else if (!strncmp(name, "log:", 4)) {
         ret = create_service_thread(log_service, get_log_file_path(name + 4));
-#endif
     } else if(!HOST && !strncmp(name, "shell:", 6)) {
         if(name[6]) {
-            ret = create_subprocess(SHELL_COMMAND, "-c", name + 6);
+            ret = create_subproc_thread(name + 6);
         } else {
-            ret = create_subprocess(SHELL_COMMAND, "-", 0);
+            ret = create_subproc_thread(0);
         }
-#if !ADB_HOST
     } else if(!strncmp(name, "sync:", 5)) {
         ret = create_service_thread(file_sync_service, NULL);
     } else if(!strncmp(name, "remount:", 8)) {
diff --git a/adb/sockets.c b/adb/sockets.c
index 43925e417..699ce27e5 100644
--- a/adb/sockets.c
+++ b/adb/sockets.c
@@ -243,6 +243,7 @@ static void local_socket_close_locked(asocket *s)
     s->closing = 1;
     fdevent_del(&s->fde, FDE_READ);
     remove_socket(s);
+    D("LS(%d): put on socket_closing_list fd=%d\n", s->id, s->fd);
     insert_local_socket(s, &local_socket_closing_list);
 }
 
@@ -250,6 +251,8 @@ static void local_socket_event_func(int fd, unsigned ev, void *_s)
 {
     asocket *s = _s;
 
+    D("LS(%d): event_func(fd=%d, ev=%04x)\n", s->id, s->fd, ev);
+
     /* put the FDE_WRITE processing before the FDE_READ
     ** in order to simplify the code.
     */
@@ -308,6 +311,7 @@ static void local_socket_event_func(int fd, unsigned ev, void *_s)
 
         while(avail > 0) {
             r = adb_read(fd, x, avail);
+            D("LS(%d): post adb_read(fd=%d,...) r=%d (errno=%d) avail=%d\n", s->id, s->fd, r, r<0?errno:0, avail);
             if(r > 0) {
                 avail -= r;
                 x += r;
@@ -322,6 +326,7 @@ static void local_socket_event_func(int fd, unsigned ev, void *_s)
             is_eof = 1;
             break;
         }
+        D("LS(%d): fd=%d post avail loop. r=%d is_eof=%d\n", s->id, s->fd, r, is_eof);
 
         if((avail == MAX_PAYLOAD) || (s->peer == 0)) {
             put_apacket(p);
@@ -362,6 +367,8 @@ static void local_socket_event_func(int fd, unsigned ev, void *_s)
             ** bytes of readable data.
             */
 //        s->close(s);
+        D("LS(%d): FDE_ERROR (fd=%d)\n", s->id, s->fd);
+
         return;
     }
 }
@@ -370,11 +377,11 @@ asocket *create_local_socket(int fd)
 {
     asocket *s = calloc(1, sizeof(asocket));
     if (s == NULL) fatal("cannot allocate socket");
-    install_local_socket(s);
     s->fd = fd;
     s->enqueue = local_socket_enqueue;
     s->ready = local_socket_ready;
     s->close = local_socket_close;
+    install_local_socket(s);
 
     fdevent_install(&s->fde, fd, local_socket_event_func, s);
 /*    fdevent_add(&s->fde, FDE_ERROR); */
@@ -400,7 +407,7 @@ asocket *create_local_service_socket(const char *name)
     if(fd < 0) return 0;
 
     s = create_local_socket(fd);
-    D("LS(%d): bound to '%s'\n", s->id, name);
+    D("LS(%d): bound to '%s' via %d\n", s->id, name, fd);
     return s;
 }
 
diff --git a/adb/sysdeps.h b/adb/sysdeps.h
index 74f4ed1c9..3a65a8a76 100644
--- a/adb/sysdeps.h
+++ b/adb/sysdeps.h
@@ -103,7 +103,7 @@ static __inline__  int    adb_unlink(const char*  path)
 
 static __inline__ int  adb_mkdir(const char*  path, int mode)
 {
-	return _mkdir(path);
+    return _mkdir(path);
 }
 #undef   mkdir
 #define  mkdir  ___xxx_mkdir
@@ -274,13 +274,18 @@ static __inline__  int  adb_is_absolute_host_path( const char*  path )
 #define OS_PATH_SEPARATOR_STR "/"
 
 typedef  pthread_mutex_t          adb_mutex_t;
+
+/* declare all mutexes */
+#define  ADB_MUTEX(x)   extern adb_mutex_t  x;
+#include "mutex_list.h"
+
 #define  ADB_MUTEX_INITIALIZER    PTHREAD_MUTEX_INITIALIZER
 #define  adb_mutex_init           pthread_mutex_init
 #define  adb_mutex_lock           pthread_mutex_lock
 #define  adb_mutex_unlock         pthread_mutex_unlock
 #define  adb_mutex_destroy        pthread_mutex_destroy
 
-#define  ADB_MUTEX_DEFINE(m)      static adb_mutex_t   m = PTHREAD_MUTEX_INITIALIZER
+#define  ADB_MUTEX_DEFINE(m)      adb_mutex_t   m = PTHREAD_MUTEX_INITIALIZER
 
 #define  adb_cond_t               pthread_cond_t
 #define  adb_cond_init            pthread_cond_init
diff --git a/adb/transport.c b/adb/transport.c
index 2baf340ee..2d678b230 100644
--- a/adb/transport.c
+++ b/adb/transport.c
@@ -35,24 +35,30 @@ static atransport transport_list = {
 ADB_MUTEX_DEFINE( transport_lock );
 
 #if ADB_TRACE
+#define MAX_DUMP_HEX_LEN 16
 static void  dump_hex( const unsigned char*  ptr, size_t  len )
 {
     int  nn, len2 = len;
+    // Build a string instead of logging each character.
+    // MAX chars in 2 digit hex, one space, MAX chars, one '\0'.
+    char buffer[MAX_DUMP_HEX_LEN *2 + 1 + MAX_DUMP_HEX_LEN + 1 ], *pb = buffer;
 
-    if (len2 > 16) len2 = 16;
+    if (len2 > MAX_DUMP_HEX_LEN) len2 = MAX_DUMP_HEX_LEN;
 
-    for (nn = 0; nn < len2; nn++)
-        D("%02x", ptr[nn]);
-    D("  ");
+    for (nn = 0; nn < len2; nn++) {
+        sprintf(pb, "%02x", ptr[nn]);
+        pb += 2;
+    }
+    sprintf(pb++, " ");
 
     for (nn = 0; nn < len2; nn++) {
         int  c = ptr[nn];
         if (c < 32 || c > 127)
             c = '.';
-        D("%c", c);
+        *pb++ =  c;
     }
-    D("\n");
-    fflush(stdout);
+    *pb++ = '\0';
+    DR("%s\n", buffer);
 }
 #endif
 
@@ -192,6 +198,7 @@ write_packet(int  fd, const char* name, apacket** ppacket)
 static void transport_socket_events(int fd, unsigned events, void *_t)
 {
     atransport *t = _t;
+    D("transport_socket_events(fd=%d, events=%04x,...)\n", fd, events);
     if(events & FDE_READ){
         apacket *p = 0;
         if(read_packet(fd, t->serial, &p)){
@@ -221,8 +228,8 @@ void send_packet(apacket *p, atransport *t)
     print_packet("send", p);
 
     if (t == NULL) {
-        fatal_errno("Transport is null");
         D("Transport is null \n");
+        fatal_errno("Transport is null");
     }
 
     if(write_packet(t->transport_socket, t->serial, &p)){
@@ -1069,4 +1076,3 @@ int check_data(apacket *p)
         return 0;
     }
 }
-
diff --git a/adb/usb_linux.c b/adb/usb_linux.c
index cd610831a..ee5d1a49c 100644
--- a/adb/usb_linux.c
+++ b/adb/usb_linux.c
@@ -45,7 +45,7 @@
 /* usb scan debugging is waaaay too verbose */
 #define DBGX(x...)
 
-static adb_mutex_t usb_lock = ADB_MUTEX_INITIALIZER;
+ADB_MUTEX_DEFINE( usb_lock );
 
 struct usb_handle
 {
diff --git a/adb/usb_linux_client.c b/adb/usb_linux_client.c
index 0a21c6f2c..635fa4bbb 100644
--- a/adb/usb_linux_client.c
+++ b/adb/usb_linux_client.c
@@ -83,14 +83,14 @@ int usb_write(usb_handle *h, const void *data, int len)
 {
     int n;
 
-    D("[ write %d ]\n", len);
+    D("about to write (fd=%d, len=%d)\n", h->fd, len);
     n = adb_write(h->fd, data, len);
     if(n != len) {
-        D("ERROR: n = %d, errno = %d (%s)\n",
-            n, errno, strerror(errno));
+        D("ERROR: fd = %d, n = %d, errno = %d (%s)\n",
+            h->fd, n, errno, strerror(errno));
         return -1;
     }
-    D("[ done ]\n");
+    D("[ done fd=%d ]\n", h->fd);
     return 0;
 }
 
@@ -98,13 +98,14 @@ int usb_read(usb_handle *h, void *data, int len)
 {
     int n;
 
-    D("[ read %d ]\n", len);
+    D("about to read (fd=%d, len=%d)\n", h->fd, len);
     n = adb_read(h->fd, data, len);
     if(n != len) {
-        D("ERROR: n = %d, errno = %d (%s)\n",
-            n, errno, strerror(errno));
+        D("ERROR: fd = %d, n = %d, errno = %d (%s)\n",
+            h->fd, n, errno, strerror(errno));
         return -1;
     }
+    D("[ done fd=%d ]\n", h->fd);
     return 0;
 }