Logging & other output concerns

[bitprophet]

Turning this into a general "how to do logging and useful output controls for invoke and fabric 2" ticket.

Use cases

• Display the task or tasks being invoked so users can follow the "flow" of nontrivial execution
  • plus parameters
  • plus dependency chain info
  • even skipped/satisfied dependencies
• Display subprocess commands being called so users can tell what's actually being done on their behalf
  • plus which task is currently in play (optionally) in case the per-task info has already scrolled by
• Display some sort of 'prefix', on a line-by-line basis, prepended to subprocess stdout/err - such as the command, task or task parameter that spawned it
  • Command itself less likely (esp since most command strings tend to be long) but task or task param is useful for things like parallel execution (#63) or Fabric per-host exec.
• Probably more besides...
• Must be able to turn a lot of this off or on at will
• May require an entirely different stdout/err mirroring/display mode when prefixes are enabled, since otherwise they'd get in the way of bytewise output (think Unicode decoding, interactive sessions, etc)

Older thoughts

Thoughts for now, jumping off of the description of fabric/fabric#57 & current state of things in Invoke master:

• Re: log lib to use:
  • May not do anything besides stdlib logging after all, it's still the most-used option, and the core problem of "what to log, when, and how" is not going to change drastically even if we use another lib. It's Not That Bad, Really™.
  • Structlog came around after that original ticket started, and actually looks like the best option if we want to add anything on top of stdlib (in part as it's the only major one that supports 2.6-3.x, has lots of good features, actually runs on top of stdlib or whatever you want, and I am mildly biased as I know the author :3)
  • Twiggy is 2.x only, so nope.
  • Logbook is 2.7-3.x, so until we're comfortable dropping 2.6 (not for a while...) it's also a no-go. Still a decent looking option otherwise.
• Log a lot of things by default, mostly at DEBUG for, well debugging. E.g. logic paths used, etc - good for troubleshooting.
  • Invoke does this already; it simply offers invoke.utils.debug (w/ setup to add other levels easily) that logs to a package-level logger. Could probably be expanded some, it's mostly used in the parsing and config modules.
• Log 'operational' level things as INFO or similar, sans any 'large' fields - i.e. log when run is called, on which host (in Fabric), with which command (tho this may want truncating...), run-time, etc - but not the stdout/stderr contents (though sizes of those, similar to HTTP log formats, is probably good).
  • Basically, the same data we expose in Result objects.
  • Re: this ticket's original aegis, DO we want to be logging the stdout/stderr ever, at any point? Or should we rely on users' ability to redirect those streams where they need?
  • They could, for example, just point both at their process' stdout/err, which would mix log output with command stdout/stderr well enough...
• I was wondering whether to log both the initiation of, and completion of, actions, or just completion (as above). Seems like best is to log initiation as DEBUG or something else below INFO (since you mostly care when troubleshooting) and completion as INFO.
• When I started fabric/fabric#57 way back, I was assuming we'd want ALL output to use the logging system, with an open question about how to handle bytewise output (as it's not line-based).
  • I no longer think this makes sense - simply log a lot of stuff, as above, and don't forward it to stdout/stderr by default.
  • Allow users to determine where their logs go (usually to a file).
  • When run via the CLI, default to a "Fabric 1-like" mode where basic info is printed to stdout/stderr - what task is run, what command is run, hook up its stdout/err, file transfer info, etc.
  • When NOT run via the CLI, probably default to no output at all - expect users to supply desired file-like objects to e.g. run's stream arguments, and to configure logging to taste.
  • Users wanting a 'hybrid' setup would do what I mentioned above, point both the runners' streams AND the logging framework to system pipes.
• Regarding Fabric specifically, how to handle multi-host invocation?
  • Having line prefixes is still useful for some use cases (especially, but not only, for parallel execution), which also means, we probably do want to retain a line-buffer at some level
  • Having 'headers' is another useful mode I've wanted at times, where I don't want the clutter of line prefixes, but do want to be able to read output sequentially and tell what happened on which host.

Original/outdated description

Right now stdout/stderr is printed in our Popen subclass byte-by-byte to allow interaction etc. However, eventually we'll want real logging, meaning an ability to throw things line-by-line into a log library, meaning an extra buffer at the Popen level that does additional Things with lines as they are tallied up.

I suppose there should be an option to turn off the bytewise in favor of just linewise, but that could be a 2nd tier thing or saved for when we start layering Fab 2 on top of this.

[bitprophet]

Calling out #546 and #547 as recently filed tickets with specifically phrased use cases that fall under this aegis.

[gitaarik]

So what's the work need to be done here? Just use Python's logging module instead of print() statements? That shouldn't be too hard? I could do a pull request.

I assume you want to log the output of the command, and with logging formatting you can control whether the command itself is shown and whether the hostname is shown?

So something like:

c.run('ls')

Would output something like:

file1 file2 file3

And:

import logging
logging.basicConfig(format="%(command)s\n%(output)s")
c.run('ls')

Would output something like:

ls
file1 file2 file3

and

import logging
logging.basicConfig(format="[%(hostname)] %(command)s\n%(output)s")
c.run('ls')

Would output something like:

[myhost] ls
file1 file2 file3

Am I on the right track here?

[anarcat]

in stressant, i add a logging output level called OUTPUT to log command standard output, for what that's worth. it's kind of nasty, but it works. i'm thinking of rewriting stresssant with invoke, so i'd be very interested in seeing how this could work.

i call the logging function once per line, that said, not once per command. maybe that's bad, but i need this to show that stuff on the console, so i had no way around that that i found elegant.

[gitaarik]

I've created my own run() and cd() methods for now that print the logging that I want:

from textwrap import indent

class Color:
    # Terminal text color escape characters
    PURPLE = '\033[95m'
    CYAN = '\033[96m'
    DARKCYAN = '\033[36m'
    BLUE = '\033[94m'
    GREEN = '\033[92m'
    YELLOW = '\033[93m'
    RED = '\033[91m'
    BOLD = '\033[1m'
    UNDERLINE = '\033[4m'
    END = '\033[0m'

def run(conn, command, sudo_pass=None):
    """
    At the time of writing, Fabric 2 doesn't have a way to show the hostname in
    front of the command. So we do it manually here.

    This GitHub issue is working on solving this in Fabric 2:
    https://github.com/pyinvoke/invoke/issues/15
    """

    print(f"{Color.BOLD}[{conn.host}] {command}{Color.END}\n")

    if sudo_pass:
        result = conn.sudo(command, hide=True, echo=False, password=sudo_pass)
    else:
        result = conn.run(command, hide=True, echo=False)

    output = indent(result.stdout or result.stderr, '    ')

    print(output)

@contextmanager
def cd(conn, path):
    """
    For the same reason we define our own `run()` command, we also have our own
    `cd()` command so we can log elaborate output to the user.

    Because this method should be a contextmanager, we can't use the original
    `cd()` method, but we can mimic it's functionality, by updating the value
    of `Connection.command_cwds`.
    """

    print(f'\n{Color.BOLD}[{conn.host}] entering dir {path}{Color.END}\n')
    conn.command_cwds.append(path)

    try:
        yield
    finally:
        print(f'\n{Color.BOLD}[{conn.host}] leaving dir {path}{Color.END}\n')
        conn.command_cwds.pop()

[anarcat]

after fiddling around with fabric for a few more days, one thing i'm missing is a --verbose flag. we already have --debug in the fab commandline, which turns debugging all the way up to 11 (loglevel=DEBUG), but i often send stuff to the INFO level for some tasks.

for example, take this script:

https://gitweb.torproject.org/admin/tsa-misc.git/tree/fabric_tpa/decom.py?id=2698d3e0ece4de7ae4059f7a51860555e607a570#n100

it has a main() because i want to setup logging so that when --verbose passed to the script, i see those neat logging.info messages come up. but by default, the script silently does its magic (more or less - it's not finished yet).

if fab had a --verbose argument that did the right thing, i wouldn't need this main at all! :)

(well, that's not true: that script is complicated by the fact that it operates on three different servers, so the task would at least need to be rewire just so, but still...)

update: i added #706 to show what i mean. probably incomplete... i wonder if another part of this would be to convert a precious few of the current debug statement into info level logs so that we would get some logging by default in "verbose"... (say "connecting to server", "runnin command" or something like that, instead of the flood of stuff from paramiko and Context we currently get...)

[anarcat]

here's another hack I used:

class VerboseProgram(Fab):
    # cargo-culted from fab's main.py
    def __init__(self, *args, **kwargs):
        super().__init__(*args,
                         executor_class=Executor,
                         config_class=Config,
                         **kwargs)

    def core_args(self):
        core_args = super().core_args()
        extra_args = [
            Argument(
                names=('verbose', 'v'),
                kind=bool,
                default=False,
                help="be more verbose"
            ),
        ]
        return core_args + extra_args

    def parse_core(self, argv):
        super().parse_core(argv)
        if self.args.debug.value:
            logging.getLogger('').setLevel(logging.DEBUG)
        elif self.args.verbose.value:
            logging.getLogger('').setLevel(logging.INFO)
        # reset formatter
        logging.debug('reseting logging formats')
        for h in logging.getLogger('').handlers:
            f = logging.Formatter()
            h.setFormatter(f)
        # override default logging policies in submodules
        #
        # without this, we get debugging info from paramiko with --verbose
        for mod in 'fabric', 'paramiko', 'invoke':
            logging.getLogger(mod).setLevel('WARNING')

kind of clunky, but it seemed better than hacking up my own wrapper to a task, which is what i was doing before (and required duplicating the argument parsing logic).