Git.execute debug message has misleading Popen(shell=...)

[EliahKagan]

While investigating #1685, I noticed that in the debug logging Git.execute does to offer insight on the Popen call it is about to make, a user inspecting the log would reasonably infer false information about the value passed as the shell= keyword argument.

The log message is presented as giving information about how Popen is being called, not how Git.execute has been called: the message shows Popen(...). I agree with this and I don't consider it a bug. But this means it should faithfully report what is about to be passed to Popen in cases where a user reading the log would otherwise be misled into thinking this is what has happened.

Reporting the actual shell= argument passed to Popen is also more useful to log than the argument passed to Git.execute (or its default value, as the case may be). Of course, logging both is possible, for example by adding more text like [from: None], though I am somewhat inclined to think that is not worth doing.

I am not arguing that the logged Popen(...) message needs to only show things as they really are in the call. It already replaces passwords to decrease leakage of sensitive information into logs, and it shows an istream_ok string representing the most useful information about how the istream argument to Git.execute affects what is passed as the stdin argument to Popen. (It may be that this should be logged as stdin, I'm not sure.) These are not misleading.

It may be that knowledge that shell=None is not a correct thing to pass to Popen mitigates this. But Popen accepts many arguments, and it's hard to remember what all the possible values are for all of them. Furthermore, I think there is a benefit to logging exactly what is about to be passed to Popen here: doing so would have revealed #1685 (assuming inspection of the log with Git.USE_SHELL set to True). The current way is more prone to error, because nontrivial logic follows the logging intended to make that logic's effect clear; so the log can show False even when True is passed.

Possible solutions

Currently, when shell is implicitly or explicitly None, the log shows lines of the form (with the ... filled in):

Popen(..., shell=None, ...)

I think the best approach is the simple one. This and #1685 can be fixed together by setting the shell variable to self.USE_SHELL when shell started out as None, then using shell both the log.debug and the Popen calls. In the log, that would give, assuming USE_SHELL is its default False value:

Popen(..., shell=False, ...)

However, we could show both:

Popen(..., shell=False [from: None], ...)

A mentioned above, I favor the former, simpler way. But I thought the latter was worth mentioning, because it is another way to show the information without misleading the user.

I've opened #1687, which fixes this (along with #1685) in the first way.

[Byron]

I couldn't agree more with the argument of logging what would be passed to Popen and also think the fix with the least complexity is the way to go.

It already replaces passwords to decrease leakage of sensitive information into logs, and it shows an istream_ok string representing the most useful information about how the istream argument to Git.execute affects what is passed as the stdin argument to Popen. (It may be that this should be logged as stdin, I'm not sure.) These are not misleading.

Nowadays I also am not a huge fan anymore of the terms istream and ostream that are, hopefully consistently, used across the codebase, but hope that in this case it would be preferable to use a more standard name for it especially since it's used in the context of spawning processes. If you see an opportunity to use stdin and maybe stdout more, please feel free to make such adjustments the next time you get a chance. Thank you.

[EliahKagan]

I looked through the code, and istream and ostream are heavily used, including in gitdb, but the usage appears consistent. Changing many of them would also, I think, be a breaking change. Additionally, because changing parameters called that would be breaking, changing other variables with those names might have the unintended effect of making it seem like the variables were the effect of importing stdin and stdout from sys (even though they were not). So while I certainly don't want to say such changes should never be made, I didn't see a good opportunity to make them; but I also didn't see other areas in the code where those names seemed to be causing any problems.

In contrast, istream in the Popen(...) message written to the log is definition intended to document what is passed as the stdin argument to Popen, and I would say in particular to document how it is based on but different from what is passed as the istream argument to Git.execute. This was obscured--or in any case it was less apparent to me--by the way the istream_ok string was built, in contrast to how the nonidentical but corresponding Popen it represents is selected.

So I've changed istream= in that message to stdin= in #1688, among other related changes.