Take logging to the next level

When building a YOCTO based build in CI, normally you would get something like the following in your build log

1 2 3 4 5 6 7

Sstate summary: Wanted 0 Found 0 Missed 0 Current 60 (0% match, 100% complete) NOTE: Executing Tasks NOTE: Setscene tasks completed NOTE: Running task 272 of 272 (/build/my-recipes/python3-systemdlint-native/python3-systemdlint-native_1.1.12.bb:do_addto_recipe_sysroot) NOTE: recipe python3-systemdlint-native-1.1.12-r0: task do_addto_recipe_sysroot: Started NOTE: recipe python3-systemdlint-native-1.1.12-r0: task do_addto_recipe_sysroot: Succeeded NOTE: Tasks Summary: Attempted 272 tasks of which 271 didn't need to be rerun and all succeeded.

depending on your build this could go on for hundreds or thousands of lines.
If there is an error or a warning, typically one would use some sort of regular expression to filter out these items and present them somehow to the user.
Unfortunately sometimes warnings and errors are multi-line and coding regex for them is just a nightmare.
There is also a file call "qa.log" but it does only log issues found by insane.bbclass so all other items, like patch-fuzz, dangling appends, custom warnings are not logged there.

So what we actually need in this situation is only the necessary data in a (preferably) structured easy to parse format - and one that catches them all.

Upstream to the rescue

Lucky us somebody contributed a very nice way to tackle the issue: BB_LOGCONFIG which is available for master and dunfell at the moment.
This uses the full power of python logging framework to make logging from bitbake super flexible and extremely powerful.

What do I need

All you need is a json file describing the setup of logging and a reference to the setting file.

The json

An example could look like this

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33

{ "formatters": { "plainFormatter": { "format": "%(levelname)s: %(message)s" } }, "handlers": { "console_stdout": { "class": "logging.StreamHandler", "formatter": "plainFormatter", "level": "INFO", "stream": 0 }, "warnings_only": { "backupCount": 10, "class": "logging.handlers.RotatingFileHandler", "filename": "warnings_only.log", "formatter": "plainFormatter", "level": "WARNING", "maxBytes": 1048576, "mode": "a" } }, "loggers": { "BitBake": { "handlers": [ "warnings_only", "console_stdout" ] } }, "version": 1 }

It is structured into a

• formatters section, which defines the format of the log message to be printed.
• handlers section, which defines the targets to log to
• and a loggers section, defining to which bitbake internal logging sources we attach to

In this example for instance 2 logger are defined

• one called "console_out", which (you might have guessed it) logs to standard out in the format defined by "plainFormatter" at the top.
  it would output the same as the example at the very beginning, so local development is still possible
• the other one called "warnings_only" logs with the same format but 
• to a file called "warnings_only.log"
• only WARNING and ERROR entries (which eliminates a lot of clutter)
• each log file can be up to 1MB in size and a maximum of 10 logfiles will be stored
  after that they will be automatically rotated

Nice, but you now may ask, 

where is the structured data? We just redirected the log, I could do the with tee and grep in no time

and you're absolutely right

Plain structure data

Unfortunately python doesn't offer any good logging formatter for structured data out of the box - like json or yaml a.s.o. - so you could at least come up with an easy to parse format.
We will alter the configuration from above to

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36

{ "formatters": { "plainFormatter": { "format": "%(levelname)s: %(message)s" }, "logfileFormatter": { "format": "-----BEGIN-----\n%(levelname)s: %(message)s\n-----END-----" } }, "handlers": { "console_stdout": { "class": "logging.StreamHandler", "formatter": "plainFormatter", "level": "INFO", "stream": 0 }, "warnings_only": { "backupCount": 10, "class": "logging.handlers.RotatingFileHandler", "filename": "warnings_only.log", "formatter": "logfileFormatter", "level": "WARNING", "maxBytes": 1048576, "mode": "a" } }, "loggers": { "BitBake": { "handlers": [ "warnings_only", "console_stdout" ] } }, "version": 1 }

now in the log file you would get

1 2 3 4 5 6

-----BEGIN----- WARNING: recipe python3-systemdlint-native-1.1.12-r0: task do_addto_recipe_sysroot: severe things happened -----END----- -----BEGIN----- WARNING: recipe python3-foo-native_1.2.3-r0: task do_compile: another warning -----END-----

this should be parseable by some script without much hardship.

Adding the real thing

Luckily somebody wrote a "real" json formatter for python logging - BUT BEWARE this needs to be installed to the build host. But as you should build within a container anyway (as it decouples the build host from the required YOCTO software stack) just add

1	pip install jsonformatter

to your e.g. Dockerfile.
And now you can change the setting form above to

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40

{ "formatters": { "plainFormatter": { "format": "%(levelname)s: %(message)s" }, "logfileFormatter": { "class": "jsonformatter.JsonFormatter", "format": { "levelname": "levelname", "message": "message" } } }, "handlers": { "console_stdout": { "class": "logging.StreamHandler", "formatter": "plainFormatter", "level": "INFO", "stream": 0 }, "warnings_only": { "backupCount": 10, "class": "logging.handlers.RotatingFileHandler", "filename": "warnings_only.log", "formatter": "logfileFormatter", "level": "WARNING", "maxBytes": 1048576, "mode": "a" } }, "loggers": { "BitBake": { "handlers": [ "warnings_only", "console_stdout" ] } }, "version": 1 }

and you will super easy to parse log file like this one here

1 2	{ "levelname": "WARNING", "message": "recipe python3-systemdlint-native-1.1.12-r0: task do_addto_recipe_sysroot: severe things happened" } { "levelname": "WARNING", "message": "recipe python3-foo-native_1.2.3-r0: task do_compile: another warning" }

and from here on you can even push this to your grafana/elastistack to have some nice visualization.

Activating the final config

That's pretty easy, as BB_LOGCONFIG is part of the EXTRAWHITE list you can define it in the same environment as you make the bitbake call. E.g. like this

1	BB_LOGCONFIG=/my/log/config.json bitbake my-image

you can have even different configs for different steps

Conclusion

Although not that thoroughly promoted by the project I think this is a huge step forward and I encourage all of you to use it as it's easy to use and super flexible to adapt your setup to any future change required