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