Default logging is noisy and not too useful

[aigarius]

Here is an example of how the default logging configuration looks in action:

sh.command: INFO: <Command '/usr/bin/git add tes...(6 more)' call_args {'in': None, 'no_out...(509 more)>: starting process

You will notice that both the executed command and arguments are cut off and unusable. At the same time the message is logged at INFO level.

First the application or library should not make assumptions about what is a good logging line size - people log to files, to logging servers and even to log aggregators that process megabytes of logs per second effortlessly. There should not be any ellipsing of the log data.

IMHO there is too much data for the INFO level. There is no need for the "<Command " or the call_args there. The INFO level message (either should not be there at all or) should just say "sh.command: INFO: '/usr/bin/git add testfile' started, pid 1232" and then have a DEBUG level message directly after that with full call_args data dumped into the line.

And if there is a start message, there should also be a stop message at the same log level. That is why you need the pid to link together via logs multiple instances of the same command starting and stopping from multiple threads.

[jf---]

True, its not particularly useful...
Also, I havent seen a flag to turn off logging?

[aigarius]

You can control logging via default Python logging module settings. Like this:
logging.getLogger("sh.command").setLevel(logging.ERROR)

[amoffat]

I cleaned up the logging a bit more. Now the logging output is not truncated, and there is a ending logging message for processes that complete. Messages also include the pid, but exclude the call args.

I am leaving the default logging level to be INFO however, and the format of the info messages more or less the same. You may not see a use for it, @aigarius, but when child loggers are used and debugging logging is turned on, the <Command> and <Process> delimiters make the logs easier to read. Example:

INFO:sh.command:<Command '/bin/ls'>: starting process
DEBUG:sh.command.process:<Command '/bin/ls'>.<Process 14278 ['/bin/ls']>: started process
DEBUG:sh.command.process.streamwriter:<Command '/bin/ls'>.<Process 14278 ['/bin/ls']>.stdin: parsed stdin as a queue
DEBUG:sh.command.process:<Command '/bin/ls'>.<Process 14278 ['/bin/ls']>: <sh.StreamWriter object at 0x7fba62d6f490> ready for more input
INFO:sh.command:<Command '/bin/ls', pid 14278>: process started
DEBUG:sh.command.process:<Command '/bin/ls'>.<Process 14278 ['/bin/ls']>: acquiring wait lock to wait for completion
DEBUG:sh.command.process:<Command '/bin/ls'>.<Process 14278 ['/bin/ls']>: got wait lock
DEBUG:sh.command.process:<Command '/bin/ls'>.<Process 14278 ['/bin/ls']>: exit code not set, waiting on pid
DEBUG:sh.command.process:<Command '/bin/ls'>.<Process 14278 ['/bin/ls']>: <sh.StreamReader object at 0x7fba62d6f650> ready to be read from
DEBUG:sh.command.process.streamreader:<Command '/bin/ls'>.<Process 14278 ['/bin/ls']>.stdout: got chunk size 720: 'AUTHORS.md\t      MANIFEST\t\t   '
DEBUG:sh.stream_bufferer:acquiring buffering lock to process chunk (buffering: 1)
DEBUG:sh.stream_bufferer:got buffering lock to process chunk (buffering: 1)
DEBUG:sh.stream_bufferer:released buffering lock for processing chunk (buffering: 1)
...

These changes are on the release-1.2 branch and will ship when that ships

[aigarius]

That is ok, but looking at the example you provided it feels like having a DEBUG level message with all the args and parameters (like cwd) would be very useful in this context. Unless I misunderstand and "/bin/ls" here is actually the full command line with all arguments. In which case the DEBUG level messages could get a bit noise in the Process header level, but that is fine for DEBUG.

Edit: Having a separate DEBUG level message in sh.command with a list of args could still useful, so that it can be enabled while sh.command.process DEBUG messages can be silenced.

[amoffat]

Fair points...I honestly only ever use DEBUG when I am debugging the internals of sh, and I have not yet needed more info. I think the changes you suggested at first are good enough for now, and when we need more, we can make more changes 👍

[aigarius]

Cheers mate, thanks for the work! 👍

[samjewell]

Now the logging output is not truncated

@amoffat Is this still true? I see truncate_cap = 750 in the code still.

I share @aigarius opinion that output to STDOUT and STDERR should not be truncated at all, even to as many as 750 chars. It means that you can't use sh out of the box ("batteries included") and see what errors are actually occurring in the shell commands that you're calling, because they fall outside the 750 char limit, and you're forced to go back and add exception handling around the call to the sh command.

Would you consider removing that 750 char limit?

[ecederstrand]

There are pros and cons to logging the full stdout/stderr output.

I see your point about getting the full context without having to go back and wrap your code in a try/except and explicitly capture the full output.

On the other hand, I think it's a good principle that logging statements shouldn't be able to single-handedly break your code. That's why for example logging.error('%s %s', 'foo') prints a stack trace but does not raise an exception. If you don't put any limit on the logging message, you could potentially emit a multi-TB log message and risk:
* Exhausting disk space, effectively killing your server
* Running out of memory, also effectively killing your server
* Breaking downstream log processors
And all of the above would happen without any obvious indication about the reason, because you're still not done logging the full message.

If you're fine with those risks, then sh still allows a simple way of disabling the limit:

import sh
sh.ErrorReturnCode.truncate_cap = 10**1000

# Your code using 'sh' here