better logging, closes #323

no truncating output
end process logging message
pids in info logs

CHANGELOG.md

@@ -2,6 +2,7 @@
 
 ## 1.2 -
 
+*   improved logging output [#323](https://github.com/amoffat/sh/issues/323)
 *   bugfix for python3+ where binary data was passed into a process's stdin [#325](https://github.com/amoffat/sh/issues/325)
 *   Introduced execution contexts which allow baking of common special keyword arguments into all commands [#269](https://github.com/amoffat/sh/issues/269)
 *   `Command` and `which` now can take an optional `paths` parameter which specifies the search paths [#226](https://github.com/amoffat/sh/issues/226)

sh.py

@@ -396,16 +396,19 @@ class Logger(object):
     appended to it via the context, eg: "ls -l /tmp" """
     def __init__(self, name, context=None):
         self.name = name
-        if context:
-            context = context.replace("%", "%%")
-        self.context = context 
         self.log = logging.getLogger("%s.%s" % (SH_LOGGER_NAME, name))
+        self.set_context(context)
 
     def _format_msg(self, msg, *args):
         if self.context:
             msg = "%s: %s" % (self.context, msg)
         return msg % args
 
+    def set_context(self, context):
+        if context:
+            context = context.replace("%", "%%")
+        self.context = context 
+
     def get_child(self, name, context):
         new_name = self.name + "." + name
         new_context = self.context + "." + context
@@ -455,16 +458,6 @@ def __init__(self, cmd, call_args, stdin, stdout, stderr):
             self.ran = " ".join(cmd)
 
 
-        friendly_cmd = friendly_truncate(self.ran, 20)
-        friendly_call_args = friendly_truncate(str(call_args), 20)
-
-        # we're setting up the logger string here, instead of __repr__ because
-        # we reserve __repr__ to behave as if it was evaluating the child
-        # process's output
-        logger_str = "<Command %r call_args %s>" % (friendly_cmd,
-                friendly_call_args)
-
-        self.log = Logger("command", logger_str)
         self.call_args = call_args
         self.cmd = cmd
 
@@ -520,10 +513,20 @@ def __init__(self, cmd, call_args, stdin, stdout, stderr):
         # there's currently only one case where we wouldn't spawn a child
         # process, and that's if we're using a with-context with our command
         if spawn_process:
+            # we're setting up the logger string here, instead of __repr__ because
+            # we reserve __repr__ to behave as if it was evaluating the child
+            # process's output
+            logger_str = "<Command %r>" % self.ran
+            self.log = Logger("command", logger_str)
             self.log.info("starting process")
+
             self.process = OProc(self.log, cmd, stdin, stdout, stderr,
                     self.call_args, pipe)
 
+            logger_str = "<Command %r, pid %d>" % (self.ran, self.process.pid)
+            self.log.set_context(logger_str)
+            self.log.info("process started")
+
             if should_wait:
                 self.wait()
 
@@ -541,6 +544,7 @@ def wait(self):
             else:
                 self.handle_command_exit_code(exit_code)
 
+        self.log.info("process completed")
         return self
 
 
@@ -1416,7 +1420,6 @@ def __init__(self, parent_log, cmd, stdin, stdout, stderr, call_args, pipe):
 
             self.log.debug("started process")
 
-
             if self.call_args["tty_in"]:
                 attr = termios.tcgetattr(self._stdin_fd)
                 attr[3] &= ~termios.ECHO