Skip to content

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

Closed
@EliahKagan

Description

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

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions