I've managed to get better at grepping for this and this finds some of
the stragglers. They are all file opens without closes fixed by using a
with open() context manager.
Change-Id: I7b8c8516a86558e2027cb0f01aefe2dd1849069c
There are two significant cases in Zuul where we may emit multi-line
log messages:
* Tracebacks
* Zuul config errors
When these are sent to a log file or stderr using the default
configurations, it can be difficult to work with those logs. Using
"grep" to search for messages or time periods will typically only
produce a single line of the error.
Further, on a busy system the error may be interleaved with other
log lines making extraction even harder.
To address both of these issues, add a formatter which formats every
line of a multi-line log message using the same format specifier.
This is quite readable when streaming or viewing a standard log file,
and it should cause all log lines to automatically appear in
ELK/splunk setups since they will all have the same message format.
(Though, those setups are probably better served with a native
logging configuration that sends the entire record together.)
It may be somewhat difficult if a multi-line log entry is recorded
on a busy system with multiple threads. However, some judicious
grepping should help with that since all related lineswill have the
exact same timestamp (including microseconds). Advanced users/devs
could specify a logging format with the thread id if necessary, though
I don't think we should do that by default.
Since this is implemented as a standard logging formatter, it can
be opted-out via logging config files. This enables it by default,
which I think is reasonable for new users, but if we decide that we
would prefer opt-in, that is a simple change.
Sample output:
2021-01-29 10:59:02,004 DEBUG zuul.Scheduler: Run handler awake
2021-01-29 10:59:02,004 ERROR zuul.Scheduler: Exception in run handler:
2021-01-29 10:59:02,004 ERROR zuul.Scheduler: Traceback (most recent call last):
2021-01-29 10:59:02,004 ERROR zuul.Scheduler: File "/home/corvus/git/zuul/zuul/zuul/scheduler.py", line 1254, in run
2021-01-29 10:59:02,004 ERROR zuul.Scheduler: raise Exception("Test")
2021-01-29 10:59:02,004 ERROR zuul.Scheduler: Exception: Test
2021-01-29 10:59:02,005 DEBUG zuul.Scheduler: Run handler sleeping
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader: 1 errors detected during zuultest tenant configuration loading
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader: Zuul encountered a syntax error while parsing its configuration in the
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader: repo local-project-config on branch master. The error was:
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader:
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader: extra keys not allowed @ data['trigger']['github']
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader:
2021-01-29 10:59:41,956 WARNING zuul.ConfigLoader: The error appears in the following pipeline stanza:
...
Change-Id: I6d7e7e7a9e19d46a744f9ffac8d532fc6b4bba01
Update the default server logging config to log alembic migration
info. Sometimes these can take a while, and the admin would like
to know what's up.
Change-Id: Ic7f87ea571ed2d4bdf84ef146e19fc2671e7cdc0
Currently the logging for polling is verbose. Adjust it as follows:
* In the git driver, don't list every ref we see, just log the count
so we know it's working.
* In the gerrit driver, move logging of some HTTP traffic to the
"io" logger.
* In the default logging configuration for the server, if the '-d'
option is given, do not include "io" logging. The only way to
get this extremely verbose data is now with a custom logging
config.
Change-Id: If0d5877f65296ee2a9f7f0298f8bc6664e6c2a4c
When using shallow copies of these data structures there is a race
between writing out the config to disk and some other Job or Server
coming along and updating handler filenames for that job/server before
the previous config is fully written to disk.
We can illustrate this in a simple example case:
>>> d = {'foo': { 'bar': 1 } }
>>> d1 = d.copy()
>>> d2 = d.copy()
>>> d1
{'foo': {'bar': 1}}
>>> d2
{'foo': {'bar': 1}}
>>> d1['foo']['bar'] = 2
>>> d1
{'foo': {'bar': 2}}
>>> d2
{'foo': {'bar': 2}}
>>>
Notice that the inner dict is updated in both d1 and d2 because the foo
key points at a reference to that inner dict and not a copy.
We can avoid this problem entirely using deepcopies.
Change-Id: I8c1ac002af76c516621396b13375913d5d60f092
Opening the logging config file with a context manager ensures that it
gets closed directly after writing. Without this a ResourceWarning
about an unclosed file is emitted on stderr[1].
[1]: Resource warning:
(...)/zuul/ansible/logconfig.py:164: ResourceWarning: unclosed file <_io.TextIOWrapper name='(...)/logging.json' mode='w' encoding='UTF-8'>
open(filename, 'w').write(json.dumps(self._config, indent=2))
Change-Id: I5a8421d4480761d3e5557201b6c589892f034ecb
This is useful for tracking github cache consumption.
Change-Id: Ic3cb7c82dfbbd00672b7ee3443c0da7f774db3b0
Signed-off-by: Jesse Keating <omgjlk@us.ibm.com>
The intent is that INFO should be usable to track down issues. That's
not going to work very well if the console handler is at WARN.
Change-Id: I59fbdc94efd1fcb45053183708f5486979852c81
We need to pass a working logging config to zuul_stream and ara so that
alembic migrations don't step on pre-playbook output.
Write a logging config using json, then pass its location in env vars so that
zuul_stream and ara can pick it up and pass it to dictConfig.
In support of this, create a LoggingConfig class so that we don't have
to copy key names and logic between executor.server, zuul_stream and
zuul_json. Since we have one, go ahead and use it for the server logging
config too, providing them with a slightly richer default logging
config for folks who don't provide a logging config file of their own.
The log config processing has to go into zuul.ansible because it's
needed in the bubblewrap and we don't have it in the python path
otherwise.
Change-Id: I3d7ac797fd2ee2c53f5fbd79d3ee048be6ca9366
Clark Boylan