1257516 - configure.py should save a log somewhere (maybe prepended to config.log?)

Status: RESOLVED FIXED

(Firefox Build System :: General, defect)

Description

[(not currently active) Ted Mielczarek]

As I was working on moving something to moz.configure I noticed that while configure.py prints output as it goes, it doesn't log that output anywhere. It would be good if it saved a log like configure.log for sanity checking later. Like the existing configure script, it might also be nice if the log contained slightly more verbose output than the default configure output.

It might be nice if the log was prepended to the existing config.log so that there was one place to look, and it wouldn't change as we remove old-configure, but I can deal with it either way.

Right now we have a pretty simple set of logging functions, just warn/error:
https://dxr.mozilla.org/mozilla-central/rev/5cfc10c14aaea2a449f74dcbb366179a45442dd6/build/moz.configure/util.configure#7

and checking:
https://dxr.mozilla.org/mozilla-central/rev/5cfc10c14aaea2a449f74dcbb366179a45442dd6/build/moz.configure/checks.configure#9

(Incidentally I noticed that `warn` seems to be getting used as a general-purpose logging function, so maybe we should add an `info` or something.)

Comment 1

[Mike Hommey [:glandium]]

(In reply to Ted Mielczarek [:ted.mielczarek] from comment #0)
> As I was working on moving something to moz.configure I noticed that while
> configure.py prints output as it goes, it doesn't log that output anywhere.
> It would be good if it saved a log like configure.log for sanity checking
> later. Like the existing configure script, it might also be nice if the log
> contained slightly more verbose output than the default configure output.

For the normal output of configure, mach does the logging already. (try mach showlog)

> It might be nice if the log was prepended to the existing config.log so that
> there was one place to look, and it wouldn't change as we remove
> old-configure, but I can deal with it either way.
> 
> Right now we have a pretty simple set of logging functions, just warn/error:
> https://dxr.mozilla.org/mozilla-central/rev/
> 5cfc10c14aaea2a449f74dcbb366179a45442dd6/build/moz.configure/util.configure#7
> 
> and checking:
> https://dxr.mozilla.org/mozilla-central/rev/
> 5cfc10c14aaea2a449f74dcbb366179a45442dd6/build/moz.configure/checks.
> configure#9
> 
> (Incidentally I noticed that `warn` seems to be getting used as a
> general-purpose logging function, so maybe we should add an `info` or
> something.)

I was contemplating using python's logging module.

Comment 2

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Add a logging handler class to print out configure output on stdout/stderr. r?ted

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

Comment 3

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Add a file-like class that sends writes to a callback. r?ted

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

Comment 4

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Rename error() to die() and make it take arguments like the logging module. r?ted

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

Comment 5

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Initialize a logger for the ConfigureSandbox, and use it for the help. r?ted

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

Comment 6

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Expose a sandboxed logger to moz.configure and use it. r?ted

This removes the warn() function and makes the die() function use the logger
instead of print.

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

Comment 7

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Send the debug output from our logger to config.log. r?ted

And since the file is also used for old-configure, close our handle on
the file before spawning old-configure, and make old-configure append
there instead of truncating the file.

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

Comment 8

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Allow the log_handle given to the virtualenv manager to be a file-like object. r?ted

subprocess functions doesn't directly take file-like objects, so add a
minimalistic wrapper to do the right thing instead of subprocess.call
when given a file-like object.

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

Comment 9

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Use the logger for virtualenv manager output. r?ted

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

Comment 10

[Mike Hommey [:glandium]]

I have another bunch of log-related changes, I'll attach them to this bug, even if they're not directly related to its subject.

Comment 11

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Add a unit test for check_prog(). r?ted

At the same time, shell quote the result it prints if it needs to be.

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

Comment 12

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Make the ConfigureOutputHandler keep some debug messages to print out when an error occurs. r?ted

The feature is made opt-in by using a context manager.

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

Comment 13

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Allow to assign Exceptions in the global scope. r?ted

But do not advertise it too much.

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

Comment 14

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Make check_prog opt-in to the queued debug log messages. r?ted

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

Comment 15

[Mike Hommey [:glandium]]

Attachment: MozReview Request: Bug 1257516 - Handle outputting the tail of config.log for old-configure failures from moz.configure. r?ted

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

Comment 16

[(not currently active) Ted Mielczarek]

Comment on attachment 8734643 [details]
MozReview Request: Bug 1257516 - Add a logging handler class to print out configure output on stdout/stderr. r?ted

https://reviewboard.mozilla.org/r/42417/#review39567

::: python/mozbuild/mozbuild/configure/util.py:48
(Diff revision 1)
> +    '''A logging handler class that sends info messages to stdout and other
> +    messages to stderr.
> +
> +    Messages sent to stdout are not formatted with the attached Formatter.
> +    Additionally, if they end with '... ', no newline character is printed,
> +    making the next message printed following the '... '.

Grammar nit: this reads strangely. Maybe you meant "making the next message printed follow the '...'?"

::: python/mozbuild/mozbuild/configure/util.py:77
(Diff revision 1)
> +    def emit(self, record):
> +        try:
> +            if record.levelno == logging.INFO:
> +                stream = self._stdout
> +                msg = record.getMessage()
> +                if (self._stdout_waiting == self.INTERRUPTED and

So the `INTERRUPTED` handling is just to print an extra '...' at the beginning of the line if some stderr gets printed between the checking message and the result? I'm not sure that's worth the extra complexity here, honestly.

::: python/mozbuild/mozbuild/configure/util.py:94
(Diff revision 1)
> +                    self._stdout.write('\n')
> +                    self._stdout.flush()
> +                stream = self._stderr
> +                msg = '%s\n' % self.format(record)
> +            stream.write(msg)
> +            stream.flush()

You could also `os.fdopen` the output files you get in the constructor to disable buffering:
http://stackoverflow.com/q/107705/69326

Comment 17

[(not currently active) Ted Mielczarek]

Comment on attachment 8734644 [details]
MozReview Request: Bug 1257516 - Add a file-like class that sends writes to a callback. r?ted

https://reviewboard.mozilla.org/r/42419/#review39573

::: python/mozbuild/mozbuild/configure/util.py:118
(Diff revision 1)
> +        if self._buf:
> +            lines[0] = self._buf + lines[0]
> +            self._buf = ''
> +        if not buf.endswith('\n'):
> +            self._buf = lines[-1]
> +            lines = lines[:-1]

This could just be `self._buf = lines.pop()`

Comment 18

[(not currently active) Ted Mielczarek]

Comment on attachment 8734645 [details]
MozReview Request: Bug 1257516 - Rename error() to die() and make it take arguments like the logging module. r?ted

https://reviewboard.mozilla.org/r/42421/#review39579

Comment 19

[(not currently active) Ted Mielczarek]

Comment on attachment 8734646 [details]
MozReview Request: Bug 1257516 - Initialize a logger for the ConfigureSandbox, and use it for the help. r?ted

https://reviewboard.mozilla.org/r/42423/#review39585

Comment 20

[(not currently active) Ted Mielczarek]

Comment on attachment 8734647 [details]
MozReview Request: Bug 1257516 - Expose a sandboxed logger to moz.configure and use it. r?ted

https://reviewboard.mozilla.org/r/42425/#review39587

I like this!

Comment 21

[(not currently active) Ted Mielczarek]

Comment on attachment 8734648 [details]
MozReview Request: Bug 1257516 - Send the debug output from our logger to config.log. r?ted

https://reviewboard.mozilla.org/r/42427/#review39589

Comment 22

[(not currently active) Ted Mielczarek]

Comment on attachment 8734649 [details]
MozReview Request: Bug 1257516 - Allow the log_handle given to the virtualenv manager to be a file-like object. r?ted

https://reviewboard.mozilla.org/r/42429/#review39591

::: python/mozbuild/mozbuild/virtualenv.py:174
(Diff revision 1)
> +
> +        proc = subprocess.Popen(*args, stdout=subprocess.PIPE,
> +                                stderr=subprocess.STDOUT, **kwargs)
> +
> +        for line in proc.stdout:
> +            self.log_handle.write(line)

This doesn't introduce any delay, does it? I know iterating over file handles isn't always great in Python.

Comment 23

[(not currently active) Ted Mielczarek]

Comment on attachment 8734650 [details]
MozReview Request: Bug 1257516 - Use the logger for virtualenv manager output. r?ted

https://reviewboard.mozilla.org/r/42431/#review39595

Comment 24

[(not currently active) Ted Mielczarek]

Comment on attachment 8734697 [details]
MozReview Request: Bug 1257516 - Add a unit test for check_prog(). r?ted

https://reviewboard.mozilla.org/r/42443/#review39597

Comment 25

[(not currently active) Ted Mielczarek]

Comment on attachment 8734698 [details]
MozReview Request: Bug 1257516 - Make the ConfigureOutputHandler keep some debug messages to print out when an error occurs. r?ted

https://reviewboard.mozilla.org/r/42445/#review39599

::: python/mozbuild/mozbuild/configure/util.py:98
(Diff revision 1)
>                      self._stdout_waiting = self.WAITING
>                  else:
>                      self._stdout_waiting = None
>                      msg = '%s\n' % msg
> +            elif (record.levelno < logging.INFO and
> +                    isinstance(self._keep_if_debug, bool)):

I'm not really wild about the use of `_keep_if_debug` as a tri-state here. Maybe an enum would be nicer?

Comment 26

[(not currently active) Ted Mielczarek]

Comment on attachment 8734699 [details]
MozReview Request: Bug 1257516 - Allow to assign Exceptions in the global scope. r?ted

https://reviewboard.mozilla.org/r/42447/#review39601

Comment 27

[(not currently active) Ted Mielczarek]

Comment on attachment 8734700 [details]
MozReview Request: Bug 1257516 - Make check_prog opt-in to the queued debug log messages. r?ted

https://reviewboard.mozilla.org/r/42449/#review39603

::: build/moz.configure/checks.configure:13
(Diff revision 1)
> +# ==============================================================
> +
> +# Declare some exceptions. This is cumbersome, but since we shouldn't need a
> +# lot of them, let's stack them all here. When adding a new one, put it in the
> +# _declare_exceptions template, and add it to the return statement. Then
> +# destructure in the assignment below the function declaration.

Maybe just make this a single-item tuple destructure currently to make it clearer where to add things?

Comment 28

[(not currently active) Ted Mielczarek]

Comment on attachment 8734701 [details]
MozReview Request: Bug 1257516 - Handle outputting the tail of config.log for old-configure failures from moz.configure. r?ted

https://reviewboard.mozilla.org/r/42451/#review39605

The Python is a lot nicer than the m4!

Comment 29

[Mike Hommey [:glandium]]

https://reviewboard.mozilla.org/r/42429/#review39591

> This doesn't introduce any delay, does it? I know iterating over file handles isn't always great in Python.

I haven't noticed any.

Comment 30

[Mike Hommey [:glandium]]

https://reviewboard.mozilla.org/r/42417/#review39567

> So the `INTERRUPTED` handling is just to print an extra '...' at the beginning of the line if some stderr gets printed between the checking message and the result? I'm not sure that's worth the extra complexity here, honestly.

Handling the extra '...' is only that one test. The rest is to handle not sending empty lines to stderr when stdout and stderr are not sent to the same place.

> You could also `os.fdopen` the output files you get in the constructor to disable buffering:
> http://stackoverflow.com/q/107705/69326

In e.g. tests, we're not using actual files, and fileno() doesn't return a file descriptor.

Comment 31

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2a9629aed11c
https://hg.mozilla.org/integration/mozilla-inbound/rev/c7c29d57b6c8
https://hg.mozilla.org/integration/mozilla-inbound/rev/f97bcb2eaf41
https://hg.mozilla.org/integration/mozilla-inbound/rev/12248651d3ad
https://hg.mozilla.org/integration/mozilla-inbound/rev/c2d739e9a7bc
https://hg.mozilla.org/integration/mozilla-inbound/rev/7fc90e806545
https://hg.mozilla.org/integration/mozilla-inbound/rev/450ffa461818
https://hg.mozilla.org/integration/mozilla-inbound/rev/2a6f03d3e6d4
https://hg.mozilla.org/integration/mozilla-inbound/rev/e521d0d6b1bf
https://hg.mozilla.org/integration/mozilla-inbound/rev/062e0b17553c
https://hg.mozilla.org/integration/mozilla-inbound/rev/9bcbc8d381e4
https://hg.mozilla.org/integration/mozilla-inbound/rev/7640e60c144a
https://hg.mozilla.org/integration/mozilla-inbound/rev/23b31c46e211

Comment 32

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/2a9629aed11c
https://hg.mozilla.org/mozilla-central/rev/c7c29d57b6c8
https://hg.mozilla.org/mozilla-central/rev/f97bcb2eaf41
https://hg.mozilla.org/mozilla-central/rev/12248651d3ad
https://hg.mozilla.org/mozilla-central/rev/c2d739e9a7bc
https://hg.mozilla.org/mozilla-central/rev/7fc90e806545
https://hg.mozilla.org/mozilla-central/rev/450ffa461818
https://hg.mozilla.org/mozilla-central/rev/2a6f03d3e6d4
https://hg.mozilla.org/mozilla-central/rev/e521d0d6b1bf
https://hg.mozilla.org/mozilla-central/rev/062e0b17553c
https://hg.mozilla.org/mozilla-central/rev/9bcbc8d381e4
https://hg.mozilla.org/mozilla-central/rev/7640e60c144a
https://hg.mozilla.org/mozilla-central/rev/23b31c46e211