Don't try killing processes if we already know the command finished + reduce error logging noise on Windows

[brandondong]

• PR Description

I was tinkering around with the code and then checking associated logs but even with LOG_LEVEL=error, I found there was a lot of noise on Windows.

This PR fixes two such sources:

1. Navigating through files in the Files panel
2. Navigating through branches in the Branches panel when there are a lot of commits (e.g. this repo)

More details in the comments below.

• Please check if the PR fulfills these requirements

• Cheatsheets are up-to-date (run go generate ./...)
• Code has been formatted (see here)
• Tests have been added/updated (see here for the integration test guide)
• Text is internationalised (see here)
• If a new UserConfig entry was added, make sure it can be hot-reloaded (see here)
• Docs have been updated if necessary
• You've read through your own file changes for silly mistakes etc

[brandondong]

When navigating through files in the Files panel, we always enter this Kill branch. It doesn't matter how slowly this is done. Even if the previous diff command completed however long ago, we will still try killing its (now gone) pid.

There is a string check here to suppress kill failure logs due to this reason but on Windows, the string is different (fails in GetCreationTime -> GetWindowsHandle -> error: "The parameter is incorrect.").

Fix: Don't try killing processes needlessly if we already know the command finished.

[brandondong]

I think this may be the likely culprit behind #3008.

In that thread, the theory proposed is:

1. Unrelated process X spawns process Y.
2. Process X exits.
3. Lazygit spawns a git process with the same pid as X.
4. Lazygit kills the running git process and then process Y as collateral due to process Y having ppid = X.

However, this doesn't seem to me like it matches up with the observation in that thread that this usually only happens after lazygit has been running in the background for a while. Why would it be any less likely to happen upon lazygit starting and killing its first git command if it's due to unrelated long-running processes with missing parents?

By contrast, the above issue does match up well with the symptoms. Imagine:

1. lazygit is started and runs git diff in process X which completes immediately and exits.
2. lazygit is left in the background for several hours by which process X pid is reused by an unrelated process.
3. lazygit is focused back on and runs another git diff. It first runs this stop logic which will kill process X and its children.

Checking for children creation time won't help here if these are legitimate child processes of unrelated process X.

[brandondong]

When navigating through branches with a lot of commits in the Branches panel, we always enter this error branch. The process will still be running indefinitely due to the buffered git log output so when we run the next git log, the previous process will be killed.

There is a string check here to suppress the failure logs due to this reason but on Windows, the string is different ("exit status 1").

Fix: Check whether we sent a kill signal and if so, suppress the error logs.

[jesseduffield]

Now that we've made this change, do we still need to check on signal: killed?

[brandondong]

I saw another usage of oscommands.Kill in RunAndProcessLines when the command decides it's time to stop reading. I think that could be another source of the kill signal here and should still be suppressed in logs on non-Windows where the string match is possible.

[stefanhaller]

It took me a while to understand this. There's no further change we should make, neither here nor in RunAndProcessLines, is that right? Ready to merge? This is the last PR that blocks the release, so it would be nice to finish it.

[jesseduffield]

Yeah I'm wondering if we should be doing something like this in RunAndProcessLines:

diff --git a/pkg/commands/oscommands/cmd_obj_runner.go b/pkg/commands/oscommands/cmd_obj_runner.go
index 41fedcfbc..7f209cbc4 100644
--- a/pkg/commands/oscommands/cmd_obj_runner.go
+++ b/pkg/commands/oscommands/cmd_obj_runner.go
@@ -166,6 +166,12 @@ func (self *cmdObjRunner) RunAndProcessLines(cmdObj ICmdObj, onLine func(line st
 		return err
 	}
 
+	done := make(chan struct{})
+	go func() {
+		_ = cmd.Wait()
+		close(done)
+	}()
+
 	for scanner.Scan() {
 		line := scanner.Text()
 		stop, err := onLine(line)
@@ -173,17 +179,25 @@ func (self *cmdObjRunner) RunAndProcessLines(cmdObj ICmdObj, onLine func(line st
 			return err
 		}
 		if stop {
-			_ = Kill(cmd)
+			select {
+			case <-done:
+			default:
+				_ = Kill(cmd)
+			}
 			break
 		}
 	}
 
 	if scanner.Err() != nil {
-		_ = Kill(cmd)
+		select {
+		case <-done:
+		default:
+			_ = Kill(cmd)
+		}
 		return scanner.Err()
 	}
 
-	_ = cmd.Wait()
+	<-done
 
 	self.log.Infof("%s (%s)", cmdObj.ToString(), time.Since(t))
 

[brandondong]

Just to clarify my earlier comment, I was not suggesting a change to RunAndProcessLines.

1. In tasks.go, I added a case <-opts.Stop: branch so Windows won't produce an error log on every arrow key press in the Branches panel.
2. A question was asked about whether we still need to the string check now that the case <-opts.Stop: branch is added.
3. I thought the answer was possibly yes because this stopping logic in tasks.go when you have another queued task is not the only place which can cause commands to be killed. I also saw another usage in RunAndProcessLines. So the string check could be kept so the log suppressing still works for non-Windows in these specific scenarios. On Windows, you're out of luck.
4. Looking at the code again, I think I was just completely mistaken earlier. There should be no cases where an exec.Cmd simultaneously goes through RunAndProcessLines and the function being updated in this PR, it doesn't even make sense as a concept.

I updated the PR to remove the string check. Sorry for the confusion.

[jesseduffield]

Makes sense. Nonetheless, do you think my above snippet makes sense (i.e. is it worth me raising a separate PR for that?)

[brandondong]

Makes sense to me. The command may have finished but the scanner is still reading from its internal buffer when deciding to stop or getting an error.

[jesseduffield]

Cool. For the record I tested the above snippet out and had issues with lazygit crashing. Nevertheless, this PR is good to merge.

[stefanhaller]

Makes sense to me. I'm not super familiar with the intricacies of the concurrency handling of this area of the code, so I'd like @jesseduffield to have a look too.

One thought about the commit history: it seems that the two changes in this commit are independent, so I'd prefer them to be two separate commits. And your github comments explaining the rationale for them could then be the commit messages, so that people blaming the code in the future don't have to go to github to learn about why the changes were made.

I think this may be the likely culprit behind #3008.

Sounds plausible to me. Shouldn't the PR title be reworded then? It's no longer just about reducing logging noise, but about fixing an actual bug.

[stefanhaller]

Nice, thanks for cleaning up the history. LGTM, I think this is ready to merge, but I'd still like @jesseduffield to have a look too.

[jesseduffield]

Good catch. One question

[jesseduffield]

Now that we've made this change, do we still need to check on signal: killed?

[jesseduffield]

LGTM. I wanna run this myself today to make sure there's no concurrency bugs before we merge.