Improve --debug output to show pid of processes that are started and stopped

getPid returns Nothing if the process has already been stopped, and in that
case, the pid will not be displayed. I think that would only happen if
waitForProcess or similar gets called more than once on the same process
handle though.

getPid on unix has an overhead of only a MVar read. On Windows it needs to
make a syscall, so will be probably more expensive. While the added expense
happens even when debug logging is disabled, it should be small enough
compared with the overhead of starting a process that it's not a problem.

(It does occur to me that a debugM that took an IO String could only run it
when debugging is really enabled, which would improve performance. It does
not seem possible to use the current hslogger interface to do that though;
it does not expose the information that would be needed.)

diff --git a/CHANGELOG b/CHANGELOG
index c9f7c20f9d931b5e89812d91b3b9e8ec134f48ef..4fdb0f9618625558583cdba0a36c5bc3e19d3772 100644 (file)
--- a/CHANGELOG
+++ b/CHANGELOG
@@ -16,6 +16,8 @@ git-annex (8.20200909) UNRELEASED; urgency=medium
   * addunused: Don't check .gitignores when adding files.
   * Improve the "Try making some of these repositories available"
     message, with some hints for the user for what to do.
+  * Improve --debug output to show pid of processes that are started and
+    stopped.
 
  -- Joey Hess <id@joeyh.name>  Mon, 14 Sep 2020 18:34:37 -0400
 

diff --git a/Utility/Process.hs b/Utility/Process.hs
index 02ce3a0fea992faf96f84921a4ebebaf64376961..f535d6b2fbc58932e246c485166fc3ab4df81db6 100644 (file)
--- a/Utility/Process.hs
+++ b/Utility/Process.hs
@@ -173,8 +173,9 @@ startInteractiveProcess cmd args environ = do
 -- | Wrapper around 'System.Process.createProcess' that does debug logging.
 createProcess :: CreateProcess -> IO (Maybe Handle, Maybe Handle, Maybe Handle, ProcessHandle)
 createProcess p = do
-       debugProcess p
-       Utility.Process.Shim.createProcess p
+       r@(_, _, _, h) <- Utility.Process.Shim.createProcess p
+       debugProcess p h
+       return r
 
 -- | Wrapper around 'System.Process.withCreateProcess' that does debug logging.
 withCreateProcess :: CreateProcess -> (Maybe Handle -> Maybe Handle -> Maybe Handle -> ProcessHandle -> IO a) -> IO a
@@ -182,11 +183,14 @@ withCreateProcess p action = bracket (createProcess p) cleanupProcess
        (\(m_in, m_out, m_err, ph) -> action m_in m_out m_err ph)
 
 -- | Debugging trace for a CreateProcess.
-debugProcess :: CreateProcess -> IO ()
-debugProcess p = debugM "Utility.Process" $ unwords
-       [ action ++ ":"
-       , showCmd p
-       ]
+debugProcess :: CreateProcess -> ProcessHandle -> IO ()
+debugProcess p h = do
+       pid <- getPid h
+       debugM "Utility.Process" $ unwords
+               [ describePid pid
+               , action ++ ":"
+               , showCmd p
+               ]
   where
        action
                | piped (std_in p) && piped (std_out p) = "chat"
@@ -196,11 +200,17 @@ debugProcess p = debugM "Utility.Process" $ unwords
        piped Inherit = False
        piped _ = True
 
+describePid :: Maybe Utility.Process.Shim.Pid -> String
+describePid Nothing = "process"
+describePid (Just p) = "process [" ++  show p ++ "]"
+
 -- | Wrapper around 'System.Process.waitForProcess' that does debug logging.
 waitForProcess ::  ProcessHandle -> IO ExitCode
 waitForProcess h = do
+       -- Have to get pid before waiting, which closes the ProcessHandle.
+       pid <- getPid h
        r <- Utility.Process.Shim.waitForProcess h
-       debugM "Utility.Process" ("process done " ++ show r)
+       debugM "Utility.Process" (describePid pid ++ " done " ++ show r)
        return r
 
 cleanupProcess :: (Maybe Handle, Maybe Handle, Maybe Handle, ProcessHandle) -> IO () 

diff --git a/doc/todo/report_PID___40__and_may_be_failure_details__63____41___in___34__process_done__34___debug_messages/comment_1_3b069234f20378fc231802c594eb213d._comment b/doc/todo/report_PID___40__and_may_be_failure_details__63____41___in___34__process_done__34___debug_messages/comment_1_3b069234f20378fc231802c594eb213d._comment
new file mode 100644 (file)
index 0000000..99cc831
--- /dev/null
+++ b/doc/todo/report_PID___40__and_may_be_failure_details__63____41___in___34__process_done__34___debug_messages/comment_1_3b069234f20378fc231802c594eb213d._comment
@@ -0,0 +1,12 @@
+[[!comment format=mdwn
+ username="joey"
+ subject="""comment 1"""
+ date="2020-09-24T16:32:14Z"
+ content="""
+I've added the pid.
+
+This happens at a layer that only knows the process exited, not what it was
+used for. Of course if we know the process in question the higher layer
+that uses it could be made to log something more informative, if
+the nonzero exit is really unexpected.
+"""]]