Change log level of OpenOCDDriver about labgrid HOT 10 CLOSED

Thanks is ok for me, it is just a minor annoyance.

But thanks for taking your time to look into it!

from labgrid.

1. Is there a way to change those log messages to DEBUG?

What's the reason you want to lower the log level?

You could add something like this before calling OpenOCDDriver.execute():

import logging
from labgrid.util.helper import processwrapper

processwrapper.loglevel = logging.DEBUG

This will affect all processes called with processwrapper, though.

In the long run the goal is to add hierarchical loggers to labgrid, so you are able to control logging with more precision.

2. There are some read errors (eg. Error: read_memory: read at 0x5c001004 with width=32 and count=1 failed), why are they not catched?

What to you mean by "catched"? Logged on warning/error level? The exit code from openocd seems to be 0, if that's bothering you, that's a question for the openocd community.

from labgrid.

Hi @Bastian-Krause

Is there a way to change those log messages to DEBUG?

What's the reason you want to lower the log level?

As you can see in my log, the whole OpenOCD cmd generates 40 lines of log.
Since I call OpenOCD before every test case to reset the device, I get tons of those OpenOCD log blocks.

You could add something like this before calling OpenOCDDriver.execute():

import logging
from labgrid.util.helper import processwrapper

processwrapper.loglevel = logging.DEBUG

Thanks, but this seems not to work in my case!
I have the following yaml snippet:

targets:
  main:
    drivers:
      OpenOCDDriver:
        name: "stm32_swd"
        bindings:
          interface: "stlink-v3"
        board_config: "openocd_tlv.cfg"
        load_commands:
          - "init"
          - "reset halt"
          - "flash write_image {filename}"
          - "flash verify_image {filename}"
          - "exit"

And I use it in a pytest fixture as:

@pytest.fixture()
def reset_sut(target):
    """Reset STM32 at start of each test. """
    import logging
    from labgrid.util.helper import processwrapper
    processwrapper.loglevel = logging.DEBUG

    stm32_swd = target.get_driver('BootstrapProtocol', name='stm32_swd')
    stm32_swd.execute(['init', 'reset halt', 'exit'])

Nevertheless I still get 40 lines of log on every OpenOCD call.

There are some read errors (eg. Error: read_memory: read at 0x5c001004 with width=32 and count=1 failed), why are they not catched?

What to you mean by "catched"? Logged on warning/error level? The exit code from openocd seems to be 0, if that's bothering you, that's a question for the openocd community.

I guess processwrapper only uses the exit code of OpenOCD to decide if all log lines are show as INFO or ERROR.
This can give false impressions, eg. with following line which is a non-critical OpenOCD error but shown as INFO:

                        INFO                        Error
                         v                            v
1691164458.175 15:54:18 INFO     Process:    [1069] Error: read_memory: read at 0x5c001004 with width=32 and count=1 failed
1691164458.176 15:54:18 INFO     Process:    [1069] Error executing event examine-end on target stm32h747xih6.cpu0:

I understand this is an issue of OpenOCD and I do not request any changes on that from your side!

from labgrid.

Is there a way to change those log messages to DEBUG?

What's the reason you want to lower the log level?

As you can see in my log, the whole OpenOCD cmd generates 40 lines of log. Since I call OpenOCD before every test case to reset the device, I get tons of those OpenOCD log blocks.

If you are not interested in so much output, lowering the log level to warning is not an option?

You could add something like this before calling OpenOCDDriver.execute():

import logging
from labgrid.util.helper import processwrapper

processwrapper.loglevel = logging.DEBUG

Thanks, but this seems not to work in my case! I have the following yaml snippet:

targets:
  main:
    drivers:
      OpenOCDDriver:
        name: "stm32_swd"
        bindings:
          interface: "stlink-v3"
        board_config: "openocd_tlv.cfg"
        load_commands:
          - "init"
          - "reset halt"
          - "flash write_image {filename}"
          - "flash verify_image {filename}"
          - "exit"

And I use it in a pytest fixture as:

@pytest.fixture()
def reset_sut(target):
    """Reset STM32 at start of each test. """
    import logging
    from labgrid.util.helper import processwrapper
    processwrapper.loglevel = logging.DEBUG

    stm32_swd = target.get_driver('BootstrapProtocol', name='stm32_swd')
    stm32_swd.execute(['init', 'reset halt', 'exit'])

Nevertheless I still get 40 lines of log on every OpenOCD call.

Sorry, I didn't look close enough: the loglevel is a class variable. There is a better way, though:

from labgrid.util.helper import processwrapper

@pytest.fixture
def reset_sut(target):
    """Reset STM32 at start of each test. """
    stm32_swd = target.get_driver('BootstrapProtocol', name='stm32_swd')
    processwrapper.disable_logging()
    stm32_swd.execute(['init', 'reset halt', 'exit'])
    processwrapper.enable_logging()

There are some read errors (eg. Error: read_memory: read at 0x5c001004 with width=32 and count=1 failed), why are they not catched?

What to you mean by "catched"? Logged on warning/error level? The exit code from openocd seems to be 0, if that's bothering you, that's a question for the openocd community.

I guess processwrapper only uses the exit code of OpenOCD to decide if all log lines are show as INFO or ERROR.

No, it logs everything as INFO messages.

This can give false impressions, eg. with following line which is a non-critical OpenOCD error but shown as INFO:

                        INFO                        Error
                         v                            v
1691164458.175 15:54:18 INFO     Process:    [1069] Error: read_memory: read at 0x5c001004 with width=32 and count=1 failed
1691164458.176 15:54:18 INFO     Process:    [1069] Error executing event examine-end on target stm32h747xih6.cpu0:

Maybe @Emantor (who implemented ProcessWrapper in #469) can chime in and tell us if logging stderr to a different log level is easily possible.

from labgrid.

Dear @Bastian-Krause

Thank you very much!
Your 2nd approach works for me.

I am closing this issue therefore.

@Emantor Please really see this a a low prio nice to have. I expect it to be tricky because OpenOCD only adds Error for the first error line.

from labgrid.

@GeorgeAtKistler Could you verify that OpenOCD info and error output are received separately via stdout/stderr?

from labgrid.

@Bastian-Krause How can I check this?
pytest shows me this output for live log setup. Therefore I expect it is just stdout:

If I provoke exit 1 with an invalid parameter (unknow-parameter), I get this:

from labgrid.

@GeorgeAtKistler Run the OpenOCD command manually and redirect the stdout/stderr streams into separate files, e.g.:

$ openocd --command adapter usb location "1-1.4" --file board/openocd_tlv.cfg --command init --command reset halt--command exit > /tmp/openocd-stdout.txt 2> /tmp/openocd-stderr.txt

Then check if the error/info logs are in the corresponding /tmp/openocd-*.txt files.

from labgrid.

It all lands in stderr:

> openocd --command 'adapter usb location "1-1.4"' --file board/openocd_tlv.cfg --command init --command "reset halt" --command exit > /tmp/openocd-stdout.txt 2> /tmp/openocd-stderr.txt

> ls -lh /tmp/openocd-std*
-rw-r--r-- 1 root user 2.3K Aug  8 11:56 /tmp/openocd-stderr.txt
-rw-r--r-- 1 root user    0 Aug  8 11:56 /tmp/openocd-stdout.txt

> cat /tmp/openocd-stdout.txt

> cat /tmp/openocd-stderr.txt
Open On-Chip Debugger 0.12.0
Licensed under GNU GPL v2
For bug reports, read
        http://openocd.org/doc/doxygen/bugs.html
adapter usb location: 1-1.4

Info : The selected transport took over low-level target control. The results might differ compared to plain JTAG/SWD
Info : clock speed 1800 kHz
Info : STLINK V3J8M3B5S1 (API v3) VID:PID 0483:374F
Info : Target voltage: 3.277076
Info : [stm32h747xih6.cpu0] Cortex-M7 r1p1 processor detected
Info : [stm32h747xih6.cpu0] target has 8 breakpoints, 4 watchpoints
Error: read_memory: read at 0x5c001004 with width=32 and count=1 failed
Error executing event examine-end on target stm32h747xih6.cpu0:
/usr/bin/../share/openocd/scripts/target/stm32h7x.cfg:237: Error: read_memory: failed to read memory
in procedure 'init'
in procedure 'stm32h7x_dbgmcu_mmw' called at file "/usr/bin/../share/openocd/scripts/target/stm32h7x.cfg", line 170
in procedure 'stm32h7x_mmw' called at file "/usr/bin/../share/openocd/scripts/target/stm32h7x.cfg", line 260
in procedure 'stm32h7x_mrw' called at file "/usr/bin/../share/openocd/scripts/target/stm32h7x.cfg", line 242
at file "/usr/bin/../share/openocd/scripts/target/stm32h7x.cfg", line 237
Info : starting gdb server for stm32h747xih6.cpu0 on 3333
Info : Listening on port 3333 for gdb connections
Error: read_memory: read at 0x5c001004 with width=32 and count=1 failed
Error executing event examine-end on target stm32h747xih6.cpu0:
/usr/bin/../share/openocd/scripts/target/stm32h7x.cfg:237: Error: read_memory: failed to read memory
in procedure 'init'
in procedure 'ocd_process_reset'
in procedure 'ocd_process_reset_inner' called at file "embedded:startup.tcl", line 1193
in procedure 'stm32h7x_dbgmcu_mmw' called at file "/usr/bin/../share/openocd/scripts/target/stm32h7x.cfg", line 170
in procedure 'stm32h7x_mmw' called at file "/usr/bin/../share/openocd/scripts/target/stm32h7x.cfg", line 260
in procedure 'stm32h7x_mrw' called at file "/usr/bin/../share/openocd/scripts/target/stm32h7x.cfg", line 242
at file "/usr/bin/../share/openocd/scripts/target/stm32h7x.cfg", line 237
[stm32h747xih6.cpu0] halted due to debug-request, current mode: Thread
xPSR: 0x01000000 pc: 0x0800225c msp: 0x240079c0
[stm32h747xih6.cpu0] halted due to debug-request, current mode: Thread
xPSR: 0x01000000 pc: 0x0800225c msp: 0x240079c0

from labgrid.

Thanks for verifying. Too bad, I don't see us separating the output into different log levels in the future.

from labgrid.