Closed Bug 1273673 Opened 4 years ago Closed 4 years ago

Use python logging for taskgraph generation

Categories

(Firefox Build System :: Task Configuration, task)

task
Not set

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: dustin, Assigned: dustin)

References

Details

Attachments

(3 files)

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.
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__?
Attachment #8753586 - Flags: review?(gps)
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/
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.
Attachment #8753586 - Flags: review?(gps) → review+
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
Attachment #8753900 - Flags: review?(gps) → review+
Comment on attachment 8753903 [details]
MozReview Request: Bug 1273673: log task creation, too; r?gps

https://reviewboard.mozilla.org/r/53550/#review50354
Attachment #8753903 - Flags: review?(gps) → review+
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!
Product: TaskCluster → Firefox Build System
You need to log in before you can comment on or make changes to this bug.