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.)

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
 

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 () 

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.
+"""]]