Introduce logging step reporter and logging serial reporter

[Emantor]

Description The new SerialLoggingReporter and StepLoggingReporter output step information using the logging framework. This allows the user to configure the logging output and filtering by himself using the python logging framework. The previous commits switched over all logging within labgrid to a new hierarchy:

• labgrid.* contains logging messages which are not associated with a target
• .* contains all output from drivers and resources and output for each step emitted by the driver.

The StepLoggingReporter can take a SerialLoggingReporter as input. Since the SerialLoggingReporter retains some state and only outputs lines that end with \r\n, the flush function is used to flush out the pending buffer before the StepLoggingReporter outputs logs.

Also always register both reporters when running pytest and provide configuration options to enable indentation and output of long logging results.

Indentation can be used if the logging output is for the logger is configured to be the same for all loggers, enable it with --lg-logging-indent for pytest runs: Format: "%(levelname)-8s %(name).16s: %(message)s"

    INFO     main.DistroKitSt:   → transition({'status': 'barebox'})
    INFO     main.DistroKitSt:     → transition({'status': <Status.bootstrap: 1>})
    INFO     main.DistroKitSt:       → transition({'status': <Status.off: 2>})
    INFO     main.USBPowerDri:         → off(None)
    INFO     labgrid.process: Current status for hub 1-3 [05e3:0608 USB2.0 Hub, USB 2.10, 4 ports]
    INFO     labgrid.process:   Port 1: 0100 power
    INFO     labgrid.process: Sent power off request
    INFO     labgrid.process: New status for hub 1-3 [05e3:0608 USB2.0 Hub, USB 2.10, 4 ports]
    INFO     labgrid.process:   Port 1: 0000 off
    INFO     main.USBPowerDri:         ← off(None)
    INFO     main.USBPowerDri:          ┗duration=0.5077122499933466
    INFO     main.DistroKitSt:       ← transition(None)
    INFO     main.DistroKitSt:        ┗duration=1.512932803016156
    INFO     main.USBSDMuxDri:       → sdmux_set({'mode': 'host'})
    INFO     labgrid.process: Success
    INFO     main.USBSDMuxDri:       ← sdmux_set(None)
    INFO     main.USBSDMuxDri:        ┗duration=2.0959847940248437
    INFO     main.USBStorageD:       → write_image({'filename': '/home/phoenix/work/ptx/git/labgrid-PTX-DistroKit/platform-v7a/images/sabrelite.hdimg'})
    INFO     labgrid.ManagedF: Synchronizing /home/phoenix/work/ptx/git/labgrid-PTX-DistroKit/platform-v7a/images/sabrelite.hdimg to dollysisters.discworld.emantor.de
    INFO     main.USBStorageD:         → get_size(None)
    INFO     main.USBStorageD:         ← get_size(None)
    INFO     main.USBStorageD:          ┣result=0
    INFO     main.USBStorageD:          ┗duration=0.01915904600173235
    INFO     main.USBStorageD:         → get_size(None)
    INFO     main.USBStorageD:         ← get_size(None)
    INFO     main.USBStorageD:          ┣result=0
    INFO     main.USBStorageD:          ┗duration=0.01871735299937427
    INFO     main.USBStorageD:         → get_size(None)
    INFO     main.USBStorageD:         ← get_size(None)
    INFO     main.USBStorageD:          ┣result=0
    INFO     main.USBStorageD:          ┗duration=0.01951914798701182
    INFO     main.USBStorageD:         → get_size(None)
    INFO     main.USBStorageD:         ← get_size(None)
    INFO     main.USBStorageD:          ┣result=15931539456
    INFO     main.USBStorageD:          ┗duration=0.016976686019916087
    INFO     main.USBStorageD: Writing /var/cache/labgrid/phoenix/9b76de17f2785fa9be00f38f2e4595282921da29128466b03304b7498a4acd65/sabrelite.hdimg to /dev/sde using dd.
    INFO     main.USBStorageD:       ← write_image(None)
    INFO     main.USBStorageD:        ┗duration=2.0650354670360684
    INFO     main.DistroKitSt:     ← transition(None)
    INFO     main.DistroKitSt:      ┗duration=7.182933396019507
    INFO     main.DistroKitSt:   ← transition(None)
    INFO     main.DistroKitSt:    ┗duration=7.185481628985144

Likewise, by default the StepLoggingReporter shortens long results:

    INFO     main.SerialDrive: barebox@Boundary Devices i.MX6 Quad Nitrogen6x Board:/
    INFO     main.BareboxDriv:   ← run_check(None)
    INFO     main.BareboxDriv:    ┣result=['* allow_color: 1',
    INFO     main.BareboxDriv:    ┣ '  autoboot_abort_key: any (values: "any", "ctrl-c")',
    INFO     main.BareboxDriv:    ┣ '* autoboot_timeout: 3',
    INFO     main.BareboxDriv:    ┣ […] (shortened, enable long_result for all elements)
    INFO     main.BareboxDriv:    ┗duration=0.9304373920313083

These can be enabled with --lg-logging-long-results.

Checklist

• [ ] Documentation for the feature
• [ ] The arguments and description in doc/configuration.rst have been updated
• [ ] CHANGES.rst has been updated
• [x] PR has been tested
• [ ] Man pages have been regenerated

[codecov[bot]]

Codecov Report

Merging #680 (76c8352) into master (41b297f) will increase coverage by 0.1%. The diff coverage is 76.0%.

@@           Coverage Diff            @@
##           master    #680     +/-   ##
========================================
+ Coverage    56.8%   56.9%   +0.1%     
========================================
  Files         144     144             
  Lines       10669   10764     +95     
========================================
+ Hits         6064    6135     +71     
- Misses       4605    4629     +24     

Impacted Files	Coverage Δ
labgrid/driver/openocddriver.py	40.5% <0.0%> (ø)
labgrid/driver/sigrokdriver.py	37.1% <0.0%> (ø)
labgrid/driver/usbstoragedriver.py	40.9% <0.0%> (ø)
labgrid/driver/xenadriver.py	56.0% <0.0%> (ø)
labgrid/resource/ethernetport.py	26.7% <50.0%> (ø)
labgrid/util/helper.py	75.7% <50.0%> (ø)
labgrid/stepreporter.py	68.2% <72.2%> (+15.8%)	:arrow_up:
labgrid/binding.py	91.9% <85.7%> (-0.8%)	:arrow_down:
labgrid/driver/bareboxdriver.py	62.3% <100.0%> (ø)
labgrid/driver/dockerdriver.py	94.7% <100.0%> (ø)
... and 17 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more Δ = absolute <relative> (impact), ø = not affected, ? = missing data Powered by Codecov. Last update 41b297f...76c8352. Read the comment docs.

[Emantor]

Sample output in a gist: https://gist.github.com/Emantor/96fb6bc60036f563569f2f6ea2215c3b

[rohieb]

This works fine on its own, but it doesn't seem to be compatible with --lg-colored-steps, and I cannot figure out why…

[rohieb]

Ah no, colored steps only work with -vv, although now with -vv -lg-colored-steps --lg-logging-indent I get two different log lines for every log item. So everything works as intended, and this is at most a documentation issue, I think.

[Emantor]

The colorization of the logging output should be done within

Ah no, colored steps only work with -vv, although now with -vv -lg-colored-steps --lg-logging-indent I get two different log lines for every log item. So everything works as intended, and this is at most a documentation issue, I think.

Yes, this is not a replacement for the existing step pytest reporter (which rewrites the terminal output) and instead uses the python logging interface. The step pytest reporter is still available and if both are active you'll get one line from the step reporter and one python logging line.

[Emantor]

Currently getLogger does not work nicely on the exporter:

labgrid-staging-exporter[19036]: add resource rl10-usb-oben-p1/USBSerialPort: USBSerialPort/OrderedDict([('match', OrderedDict([('@ID_PATH', 'pci-0000:01:00.0-usb-0:1.3.3')]))])
labgrid-staging-exporter[19036]: Traceback (most recent call last):
labgrid-staging-exporter[19036]:   File "/usr/ptx-venvs/labgrid-staging/lib/python3.7/site-packages/labgrid/remote/exporter.py", line 658, in onJoin
labgrid-staging-exporter[19036]:     group_name, resource_name, cls, params
labgrid-staging-exporter[19036]:   File "/usr/ptx-venvs/labgrid-staging/lib/python3.7/site-packages/labgrid/remote/exporter.py", line 752, in add_resource
labgrid-staging-exporter[19036]:     proxy_required=proxy_req)
labgrid-staging-exporter[19036]:   File "<attrs generated init labgrid.remote.exporter.SerialPortExport>", line 8, in __init__
labgrid-staging-exporter[19036]:     self.__attrs_post_init__()
labgrid-staging-exporter[19036]:   File "/usr/ptx-venvs/labgrid-staging/lib/python3.7/site-packages/labgrid/remote/exporter.py", line 188, in __attrs_post_init__
labgrid-staging-exporter[19036]:     self.local = USBSerialPort(target=None, name=None, **self.local_params)
labgrid-staging-exporter[19036]:   File "<attrs generated init labgrid.resource.udev.USBSerialPort>", line 21, in __init__
labgrid-staging-exporter[19036]:     self.__attrs_post_init__()
labgrid-staging-exporter[19036]:   File "/usr/ptx-venvs/labgrid-staging/lib/python3.7/site-packages/labgrid/resource/udev.py", line 235, in __attrs_post_init__
labgrid-staging-exporter[19036]:     super().__attrs_post_init__()
labgrid-staging-exporter[19036]:   File "/usr/ptx-venvs/labgrid-staging/lib/python3.7/site-packages/labgrid/resource/udev.py", line 63, in __attrs_post_init__
labgrid-staging-exporter[19036]:     self.log = self.get_logger()
labgrid-staging-exporter[19036]:   File "/usr/ptx-venvs/labgrid-staging/lib/python3.7/site-packages/labgrid/binding.py", line 112, in get_logger
labgrid-staging-exporter[19036]:     self.target.name, self.__class__.__name__
labgrid-staging-exporter[19036]: AttributeError: 'NoneType' object has no attribute 'name'
labgrid-staging-exporter[19036]: Exception ignored in: <function SerialPortExport.__del__ at 0x7f7df22068c8>
labgrid-staging-exporter[19036]: Traceback (most recent call last):
labgrid-staging-exporter[19036]:   File "/usr/ptx-venvs/labgrid-staging/lib/python3.7/site-packages/labgrid/remote/exporter.py", line 198, in __del__
labgrid-staging-exporter[19036]:     if self.child is not None:
labgrid-staging-exporter[19036]: AttributeError: 'SerialPortExport' object has no attribute 'child'

Edit: This was already fixed in this PR, our staging environment was not updated.

[Emantor]

Superceded by https://github.com/labgrid-project/labgrid/pull/1022