Closed Bug 1257516 Opened 8 years ago Closed 8 years ago

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

Categories

(Firefox Build System :: General, defect)

defect
Not set
normal

Tracking

(firefox48 fixed)

RESOLVED FIXED
mozilla48
Tracking Status
firefox48 --- fixed

People

(Reporter: ted, Assigned: glandium)

References

(Blocks 1 open bug)

Details

Attachments

(13 files)

58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
58 bytes, text/x-review-board-request
ted
: review+
Details
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.)
(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.
Blocks: pyconfigure-infra
No longer blocks: pyconfigure
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/
Attachment #8734647 - Flags: review?(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/
Attachment #8734648 - Flags: review?(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/
Attachment #8734649 - Flags: review?(ted)
Assignee: nobody → mh+mozilla
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.
Blocks: 1259381
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/
Attachment #8734697 - Flags: review?(ted)
Blocks: 1259960
Attachment #8734643 - Flags: review?(ted) → review+
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 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()`
Attachment #8734644 - Flags: review?(ted) → review+
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
Attachment #8734645 - Flags: review?(ted) → review+
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
Attachment #8734646 - Flags: review?(ted) → review+
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!
Attachment #8734647 - Flags: review?(ted) → review+
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
Attachment #8734648 - Flags: review?(ted) → review+
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.
Attachment #8734649 - Flags: review?(ted) → review+
Attachment #8734650 - Flags: review?(ted) → review+
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 on attachment 8734697 [details]
MozReview Request: Bug 1257516 - Add a unit test for check_prog(). r?ted

https://reviewboard.mozilla.org/r/42443/#review39597
Attachment #8734697 - Flags: review?(ted) → review+
Attachment #8734698 - Flags: review?(ted) → review+
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 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
Attachment #8734699 - Flags: review?(ted) → review+
Attachment #8734700 - Flags: review?(ted) → review+
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 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!
Attachment #8734701 - Flags: review?(ted) → review+
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.
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.
Depends on: 1261018
Depends on: 1261235
Depends on: 1261285
Product: Core → Firefox Build System
You need to log in before you can comment on or make changes to this bug.