This will help provide consistent, time-stamped logs for the decision task. Mach's logging isn't really documented, but logging_tree shows <--"" Level DEBUG Handler <logging.NullHandler object at 0x7f027a2d9450> | o<--"mach" | Level DEBUG | Handler Stream <open file '<stdout>', mode 'w' at 0x7f027c5c1150> | Level INFO | Formatter <mach.logging.StructuredTerminalFormatter object at 0x7f0278e45fd0> | Handler Stream <open file u'/home/dustin/p/m-c/obj-x86_64-pc-linux-gnu/.mozbuild/last_log.json', mode 'wb' at 0x7f027c4de4b0> | Level DEBUG | Formatter <mach.logging.StructuredJSONFormatter object at 0x7f0278dd6650> | | | o<--[mach.commands] | | | | | o<--[mach.commands.e64d8f781c7911e6819822000a241184] | | | | | o<--"mach.commands.e64d8f781c7911e6819822000a241184.MachCommands" | | Level NOTSET so inherits level DEBUG | | | o<--"mach.main" | Level NOTSET so inherits level DEBUG | Handler Stream <open file '<stdout>', mode 'w' at 0x7f027c5c1150> | Level INFO | Formatter <mach.logging.StructuredTerminalFormatter object at 0x7f0278e45fd0> | Handler Stream <open file u'/home/dustin/p/m-c/obj-x86_64-pc-linux-gnu/.mozbuild/last_log.json', mode 'wb' at 0x7f027c4de4b0> | Level DEBUG | Formatter <mach.logging.StructuredJSONFormatter object at 0x7f0278dd6650> | o<--[mozbuild] | o<--[mozbuild.base] | o<--"mozbuild.base.MozbuildObject" Level NOTSET so inherits level DEBUG so it looks like anything with a logger beginning with `mach` will be properly logged.

Ah, but anything there needs to be "structured" (i.e., include record.params). So I think I'm on my own to implement everything, including a handler, under a different logging namespace.

Review commit: https://reviewboard.mozilla.org/r/53374/diff/#index_header See other reviews: https://reviewboard.mozilla.org/r/53374/

Comment on attachment 8753586 [details] MozReview Request: Bug 1273673: use Python logging for taskgraph generation; r?gps https://reviewboard.mozilla.org/r/53374/#review50164 ::: taskcluster/mach_commands.py:180 (Diff revision 1) > + level = logging.DEBUG if verbose else logging.INFO > + if quiet: > + handler = logging.NullHandler() > + else: > + handler = logging.StreamHandler(sys.stderr) > + handler.setLevel(level) > + formatter = ColorizedFormatter("%(levelname)s - %(message)s", self.log_manager.terminal) > + handler.setFormatter(formatter) Did you see https://dxr.mozilla.org/mozilla-central/source/python/mach/mach/logging.py#238 and callers like https://dxr.mozilla.org/mozilla-central/source/testing/mochitest/mach_commands.py#244? This will enable unstructured messages from all loggers to go to stdout. I'm pretty sure this is what you want here. ::: testing/taskcluster/taskcluster_graph/mach_util.py:19 (Diff revision 1) > from collections import namedtuple > > ROOT = os.path.dirname(os.path.realpath(__file__)) > GECKO = os.path.realpath(os.path.join(ROOT, '..', '..', '..')) > > +logger = logging.getLogger('taskgraph.mach_util') Y u no __name__?

Review commit: https://reviewboard.mozilla.org/r/53548/diff/#index_header See other reviews: https://reviewboard.mozilla.org/r/53548/

Comment on attachment 8753586 [details] MozReview Request: Bug 1273673: use Python logging for taskgraph generation; r?gps Review request updated; see interdiff: https://reviewboard.mozilla.org/r/53374/diff/1-2/

Review commit: https://reviewboard.mozilla.org/r/53550/diff/#index_header See other reviews: https://reviewboard.mozilla.org/r/53550/

https://reviewboard.mozilla.org/r/53372/#review50294 Apologies for the two add-on patches -- they just add more uses of the logger, now that I can control levels.

Comment on attachment 8753586 [details] MozReview Request: Bug 1273673: use Python logging for taskgraph generation; r?gps https://reviewboard.mozilla.org/r/53374/#review50348 ::: taskcluster/mach_commands.py:51 (Diff revision 2) > +class ColorizedFormatter(logging.Formatter): > + """ > + Format log messages similarly to mach logging, including times offset from > + start and colorized output on TTYs. > + """ > + def __init__(self, fmt, terminal): > + super(ColorizedFormatter, self).__init__(fmt=fmt) > + self.start_time = time.time() > + self.terminal = terminal > + > + def format(self, record): > + f = super(ColorizedFormatter, self).format(record) > + t = format_seconds(record.created - self.start_time) > + if self.terminal: > + t = self.terminal.blue(t) > + return '%s %s' % (t, f) You no longer use this. So nuke it. Along with the `format_seconds` and `time` imports above.

Comment on attachment 8753900 [details] MozReview Request: Bug 1273673: log phases of taskgraph generation; r?gps https://reviewboard.mozilla.org/r/53548/#review50352

Comment on attachment 8753903 [details] MozReview Request: Bug 1273673: log task creation, too; r?gps https://reviewboard.mozilla.org/r/53550/#review50354

https://reviewboard.mozilla.org/r/53374/#review50348 > You no longer use this. So nuke it. Along with the `format_seconds` and `time` imports above. Will push with that removed. Thanks!

https://hg.mozilla.org/integration/mozilla-inbound/rev/e5349d525d9d3e60e6992d619a6cf56a270051e8 Bug 1273673: use Python logging for taskgraph generation; r=gps https://hg.mozilla.org/integration/mozilla-inbound/rev/3556175ed39ff055e1d9e310978f126267b92236 Bug 1273673: log phases of taskgraph generation; r=gps https://hg.mozilla.org/integration/mozilla-inbound/rev/ea7843420fe518b772c7b259d8ff47193fc5b79e Bug 1273673: log task creation, too; r=gps

https://hg.mozilla.org/mozilla-central/rev/e5349d525d9d https://hg.mozilla.org/mozilla-central/rev/3556175ed39f https://hg.mozilla.org/mozilla-central/rev/ea7843420fe5