Logging format in wifi component uses problematic non-standard technique

[jsam589]

I am sorry for reporting this so late in 4.1 development, but I just found two bothersome differences between 4.0 release and 4.1 beta2. (1) Many of the log messages coming from "wifi" component are broken into pieces, a technique not used anywhere else in the IDF as far as I can tell. (2) These Info level messages come through even if log level is set for Warn. The ramifications are more than just cosmetic.

1. Log messages from other components can now appear wedged in the midst of the separate pieces of a wifi message.
Example:

Code: Select all

I (19042) wifi:D (19046) esp_netif_lwip:

2. More important to me, I use esp_log_set_vprintf() and a custom log handler which expects atomic log messages with a recognizable format string (i.e. contains " (%d) %s: " as part of the format string passed in). Only the first piece of the wifi multi-part log messages contains anything like the expected string (and even that drops the space following colon) and thus the other parts cannot be associated and arrive unusable.

If my understanding of what has happened is correct, I strongly request that these be returned to the traditional log format used by all other IDF components. And also please fix the log level no longer being properly honored.

Format strings (brackets mine) in a 3-part wifi log message:
First message that arrives: [%c (%d) %s:]
Second message that arrives: [Init dynamic tx buffer num: %d]
Third message (just for newline I think): [%s]

All these together are supposed to print out as one line, e.g.:
I (9316) wifi:Init dynamic tx buffer num: 32

Messages using the non-standard technique which I have found so far:
Note: I think the source for these is in the binary-only library and I cannot actually see what the source is doing. My custom handler flagged these particular ones as having non-standard format.

Code: Select all

I (9232) wifi:wifi driver task: 3ffe9e04, prio:23, stack:3584, core=0
I (9316) wifi:wifi firmware version: aa6b3be
I (9316) wifi:config NVS flash: enabled
I (9316) wifi:config nano formating: disabled
I (9316) wifi:Init dynamic tx buffer num: 32
I (9320) wifi:Init data frame dynamic rx buffer num: 32
I (9324) wifi:Init management frame dynamic rx buffer num: 32
I (9330) wifi:Init management short buffer num: 32
I (9334) wifi:Init static tx buffer num: 16
I (9340) wifi:Init static rx buffer size: 1600
I (9344) wifi:Init static rx buffer num: 10
I (9346) wifi:Init dynamic rx buffer num: 32
I (9476) wifi:mode : sta (24:0a:c4:47:39:8c)
I (18728) wifi:flush txq
I (18736) wifi:stop sw txq
I (18740) wifi:lmac stop hw txq
I (18798) wifi:mode : sta (24:0a:c4:47:39:8c)
I (18936) wifi:new:<1,1>, old:<1,0>, ap:<255,255>, sta:<1,1>, prof:1
I (18938) wifi:state: init -> auth (b0)
I (18946) wifi:state: auth -> assoc (0)
I (18958) wifi:state: assoc -> run (10)
I (18976) wifi:connected with SensorsCallTest, aid = 1, channel 1, 40U, bssid = 58:d9:d5:29:10:b1
I (18976) wifi:security type: 4, phy: bgn, rssi: -48
I (18982) wifi:pm start, type: 1
I (19042) wifi:D (19046) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fffa320
AP's beacon interval = 102400 us, DTIM period = 3D (19054) esp_netif_lwip: if0x3fffa320 start ip lost tmr: no need start because netif=0x3fffa3a0 interval=120 ip=0

Here is example of log output from same code built with IDF 4.0 release, which my custom handler is able to process. If these did not come in atomically, they would not have succeeded.

Code: Select all

2020-06-07T01:37:05+03:00, I, 10936, "wifi", "wifi driver task: 3ffdfb14, prio:23, stack:3584, core=0"
2020-06-07T01:37:06+03:00, I, 11163, "wifi", "wifi firmware version: 581f422"
2020-06-07T01:37:06+03:00, I, 11230, "wifi", "config NVS flash: enabled"
2020-06-07T01:37:06+03:00, I, 11296, "wifi", "config nano formating: disabled"
2020-06-07T01:37:06+03:00, I, 11365, "wifi", "Init dynamic tx buffer num: 32"
2020-06-07T01:37:06+03:00, I, 11431, "wifi", "Init data frame dynamic rx buffer num: 32"
2020-06-07T01:37:06+03:00, I, 11497, "wifi", "Init management frame dynamic rx buffer num: 32"
2020-06-07T01:37:06+03:00, I, 11567, "wifi", "Init management short buffer num: 32"
2020-06-07T01:37:06+03:00, I, 11633, "wifi", "Init static tx buffer num: 16"
2020-06-07T01:37:06+03:00, I, 11700, "wifi", "Init static rx buffer size: 1600"
2020-06-07T01:37:06+03:00, I, 11769, "wifi", "Init static rx buffer num: 10"
2020-06-07T01:37:06+03:00, I, 11835, "wifi", "Init dynamic rx buffer num: 32"
2020-06-07T01:37:06+03:00, I, 11916, "wifi", "mode : sta (24:0a:c4:47:39:8c)"

[jsam589]

I restated the issue in a new forum post, including how to reproduce using IDF example code.

Linking here: viewtopic.php?f=13&t=16409

[priisen]

Hi All,

Same Issue here, wifi logging appears not to be atomic, e.g.:

Code: Select all

I (968) wifi:D (968) DBG: LABELS: 'Pete'
connected with riisen, aid = 1, channel 11, BW20, bssid = 50:6a:03:56:a5:88D (968) DBG:  MATRIX id:0 start:0 1/1 10/141

I (978) wifi:security: WPA2-PSK, phy: bgn, rssi: -61D (978) DBG: WS > {"7mNSQgUv2mNy2mdOPAM-oa8bR9sdOvoK":{"trf":{"start":1509114412,"id":0,"cur":826,"sc":0.491,"lbl":"Ted","tiers":1,"blks":0,"mode":0,"schm":0,"type":0}}}

D (998) DBG: ProcessPublishPrice

Should be:

Code: Select all

I (968) wifi:connected with riisen, aid = 1, channel 11, BW20, bssid = 50:6a:03:56:a5:88
D (968) DBG: LABELS: 'Pete'
D (968) DBG:  MATRIX id:0 start:0 1/1 10/141
I (978) wifi:security: WPA2-PSK, phy: bgn, rssi: -61
D (978) DBG: WS > {"7mNSQgUv2mNy2mdOPAM-oa8bR9sdOvoK":{"trf":{"start":1509114412,"id":0,"cur":826,"sc":0.491,"lbl":"Ted","tiers":1,"blks":0,"mode":0,"schm":0,"type":0}}}
D (998) DBG: ProcessPublishPrice

Cheers
Paul