Logging from CHIP code (CON-1243)

[jonsmirl]

I'm using this to redirect the ESP log

old_logprintf = esp_log_set_vprintf(log_callback);

That works without problem for ESP_LOG type messages, but CHIP isn't using ESP_LOG for everything.

I see this on my console

I (8315) app_main: JDS app_event_cb c000
I (8316) app_main: JDS app_event_cb 800e
I (8316) device: Interface IP Address Changed
I (8317) chip[DIS]: Updating services using commissioning mode 0
I (8319) chip[DIS]: CHIP minimal mDNS started advertising.
I (8330) chip[DIS]: Advertise operational node AF67F99EAFC7087E-DB7227D0620F0C7D
I (8332) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: AF67F99EAFC7087E-DB7227D0620F0C7D.
I (8336) chip[DIS]: mDNS service published: _matter._tcp
I (8338) chip[DIS]: Advertise operational node 92BAA20D89A92C76-AB0DE00000000022
I (8339) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 92BAA20D89A92C76-AB0DE00000000022.
I (8346) chip[DIS]: mDNS service published: _matter._tcp
I (9019) ble_cluster: BLE addr 34:f1:ae:d4:08:00
I (9020) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0xFFF3FC03's Attribute 0x00000000 is 0 **********
I (10701) ROUTE_HOOK: Received RIO

and this in the redirected log

I (8315) app_main: JDS app_event_cb c000
I (8316) app_main: JDS app_event_cb 800e
I (8316) device: Interface IP Address Changed
Updating services using commissioning mode 0CHIP minimal mDNS started advertising.Advertise operational node AF67F99EAFC7087E-DB7227D0620F0C7DCHIP minimal mDNS configured as 'Operational device'; instance name: AF67F99EAFC7087E-DB7227D0620F0C7D.mDNS service published: _matter._tcpAdvertise operational node 92BAA20D89A92C76-AB0DE00000000022CHIP minimal mDNS configured as 'Operational device'; instance name: 92BAA20D89A92C76-AB0DE00000000022.mDNS service published: _matter._tcpI (9019) ble_cluster: BLE addr 34:f1:ae:d4:08:00
I (9020) esp_matter_attribute: ********** W : Endpoint 0x0000's Cluster 0xFFF3FC03's Attribute 0x00000000 is 0 **********
I (10701) ROUTE_HOOK: Received RIO
I (10702) ROUTE_HOOK: prefix FD89:EBF4:10D6:: lifetime 1800

The log prefix "I (8317) chip[DIS]: " is missing in the redirected log.

[shubhamdp]

Logging.ccp has the implementation details about how chip SDK logs.

Log format for ESP_LOG is generated at compile time because they are macros. Whereas, chip sdk calls a platform function for redirecting the logs, and hence it's a bit tough to mend the format there.

If you see, the printf's in there is the reason for missed out I (8317) chip[DIS]: .

I'll see if this can be fixed somehow.

[jonsmirl]

The reason for this is to support debugging in the field. If you enable debugging I start a web server and which supports a URL that grabs the log buffer. So I have redirect the log into RAM instead of the console. Now there is no need for wires into the unit.

I put the code for making the MDNS entry in this issue, #1018

Then I use the webserver from ESP SDK to send the log buffer when you ask for it.

[sdrasti]

@jonsmirl @shubhamdp It seems that using chip::Logging could be an effective approach for controlling CHIP logging at runtime.

Disable all Log-Categories:

chip::Logging::SetLogFilter(chip::Logging::kLogCategory_None);

or specific categories:

chip::Logging::SetLogFilter(chip::Logging::kLogCategory_Error);
chip::Logging::SetLogFilter(chip::Logging::kLogCategory_Detail);
chip::Logging::SetLogFilter(chip::Logging::kLogCategory_Progress);
...

Creating a callback for redirecting the CHIP logging:

chip::Logging::SetLogRedirectCallback(LogRedirectCb);

The callback function supplies both the log category and log module for filtering within the handler:

LogRedirectCallback_t = void (*)(const char * module, uint8_t category, const char * msg, va_list args);

[shubhamdp]

@sdrasti, thank you for pointing out the log redirection callback in the connectedhomeip repository.

@jonsmirl, you’ll also need to set up log redirection for CHIP logs. You can refer to the following: Log Redirection in CHIP.

@jonsmirl you will have to set the log redirection for CHIP logs as well. (ref: https://github.com/project-chip/connectedhomeip/blob/master/src/lib/support/logging/TextOnlyLogging.cpp#L199)

This will prevent the current redirection through Platform::LogV(), which currently only forwards the middle part of the logs to esp_log_writev, missing the timestamp and tag.