Use python logging for taskgraph generation

RESOLVED FIXED

Status

Taskcluster
Task Configuration
RESOLVED FIXED
2 years ago
2 years ago

People

(Reporter: dustin, Assigned: dustin)

Tracking

Details

MozReview Requests

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(3 attachments)

(Assignee)

Description

2 years ago
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.
(Assignee)

Comment 1

2 years ago
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.
(Assignee)

Comment 2

2 years ago
Created attachment 8753586 [details]
MozReview Request: Bug 1273673: use Python logging for taskgraph generation; r?gps

Review commit: https://reviewboard.mozilla.org/r/53374/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/53374/
Attachment #8753586 - Flags: review?(gps)

Comment 3

2 years ago
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)
(Assignee)

Comment 4

2 years ago
Created attachment 8753900 [details]
MozReview Request: Bug 1273673: log phases of taskgraph generation; r?gps

Review commit: https://reviewboard.mozilla.org/r/53548/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/53548/
Attachment #8753900 - Flags: review?(gps)
Attachment #8753586 - Flags: review?(gps)
(Assignee)

Comment 5

2 years ago
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/
(Assignee)

Comment 6

2 years ago
Created attachment 8753903 [details]
MozReview Request: Bug 1273673: log task creation, too; r?gps

Review commit: https://reviewboard.mozilla.org/r/53550/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/53550/
Attachment #8753903 - Flags: review?(gps)
(Assignee)

Comment 7

2 years ago
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.

Updated

2 years ago
Attachment #8753586 - Flags: review?(gps) → review+

Comment 8

2 years ago
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 9

2 years ago
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+
(Assignee)

Comment 11

2 years ago
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!
(Assignee)

Comment 12

2 years ago
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
Status: NEW → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → FIXED

Comment 14

2 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/00ad215248d5

Comment 15

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/00ad215248d5

Comment 16

2 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/87219f2b44e5

Comment 17

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/87219f2b44e5
You need to log in before you can comment on or make changes to this bug.