DPP Auth Failed on dpp-enrollee example (IDFGH-9228)

[knight-ryu12]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v4.4.3

Operating System used.

Windows

How did you build your project?

VS Code IDE

If you are using Windows, please specify command line type.

PowerShell

Development Kit.

ESP32-WROVER-DevkitC

Power Supply used.

USB

What is the expected behavior?

I expected it to correctly authenticate with Accesspoint.

What is the actual behavior?

It does not authenticate with accesspoint at all;
Seems that it fails with WPA being D (66148) wpa: Mgmt Tx Status - 1, Cookie - 0x400e036c, and returns ESP_ERR_DPP_TX_FAILURE no matter what accesspoint it uses.

Steps to reproduce.

Code
It is 1:1 to the example, expect I removed the key part. which should just work without it.

Debug Logs.

D (64538) wpa: DPP: Rx Public Action frame: action - 9
I (64538) wpa: DPP: Authentication Request from ac:3e:b1:02:80:e0
D (64538) event: running post WIFI_EVENT:20 with handler 0x400d6adc and context 0x3ffbdcfc on loop 0x3ffbc9f0
0x400d6adc: event_handler(void*, char const*, int, void*) at C:/Users/Alma/sensor-data-update/main/main.cpp:55

E (64548) wpa: curve: secp256r1

E (64558) wpa: prime len is 32

E (64558) wpa: Q_x: - hexdump(len=32):
E (64568) wpa: 2e cc 68 18 67 c2 7a 7f d2 59 20 1f 89 c5 99 28
E (64568) wpa: d2 59 3b 12 b9 07 13 4d 04 02 9a 80 0e 57 69 5c
E (64578) wpa: Q_y: - hexdump(len=32):
E (64578) wpa: 52 00 62 4e d9 33 98 b6 79 86 f6 ba 1c 20 a0 34
E (64588) wpa: 6f ec 12 e8 8d 28 56 47 7e 6b 09 00 48 04 84 29 
E (64598) wpa: d:      - hexdump(len=32):
E (64598) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
E (64608) wpa: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
D (64558) event: running post WIFI_EVENT:20 with handler 0x400e0420 and context 0x3ffcf050 on loop 0x3ffbc9f0
0x400e0420: offchan_event_handler at C:/Users/Alma/esp443/esp-idf/components/wpa_supplicant/esp_supplicant/src/esp_dpp.c:449

D (64858) wpa: DPP: ECDH shared secret (M.x) - hexdump(len=32):
D (64858) wpa: f0 8c 6a ab fc 7b b8 4e 1b 6f f0 ff b7 2d a7 51
D (64858) wpa: 0a 20 b7 ac ae e7 de 04 58 42 a2 fd 44 22 44 9c 
D (64868) wpa: DPP: PRK = HKDF-Extract(<>, IKM=M.x) - hexdump(len=32):
D (64878) wpa: bc 82 9b f7 0b 3d 4d 33 4a 14 1f 11 9d d0 76 ff
D (64878) wpa: 76 f6 99 be c7 1f 2e 87 b2 8d d7 11 4f e5 ce 4f 
D (64888) wpa: DPP: k1 = HKDF-Expand(PRK, info, L) - hexdump(len=32):
D (64888) wpa: 0a e1 3c 28 f3 44 cf 2d 60 c0 f1 75 63 9d 19 4a
D (64898) wpa: 55 49 3f 69 61 4f 8a f0 68 22 7d ab 9e 0e 11 48 
D (64908) wpa: DDP: AES-SIV AD[0] - hexdump(len=6):
D (64908) wpa: 50 6f 9a 1a 01 00
D (64908) wpa: DDP: AES-SIV AD[1] - hexdump(len=145):
D (64918) wpa: 02 10 20 00 d1 29 db 70 63 65 7c e0 a6 69 1d 0e
D (64928) wpa: 7b b4 2e c4 dc b0 9b f1 70 94 43 b4 45 44 d9 d5
D (64928) wpa: c2 50 90 a7 01 10 20 00 ad 99 e9 8c 5d c3 e0 73 
D (64938) wpa: 5f 15 68 77 32 88 6c 42 64 18 88 a2 eb 22 85 52
D (64938) wpa: f3 15 f7 d4 16 d7 21 f7 03 10 40 00 2e cc 68 18 
D (64948) wpa: 67 c2 7a 7f d2 59 20 1f 89 c5 99 28 d2 59 3b 12
D (64958) wpa: b9 07 13 4d 04 02 9a 80 0e 57 69 5c 52 00 62 4e
D (64958) wpa: d9 33 98 b6 79 86 f6 ba 1c 20 a0 34 6f ec 12 e8 
D (64968) wpa: 8d 28 56 47 7e 6b 09 00 48 04 84 29 19 10 01 00
D (64968) wpa: 02
D (64978) wpa: DPP: AES-SIV ciphertext - hexdump(len=41):
D (64978) wpa: 5e 3c b5 ca a8 35 62 48 31 16 73 3f 86 1b 05 fd
D (64988) wpa: ca ee a0 d1 f2 ec c4 c2 a1 be f9 d3 f1 a5 f8 21
D (64988) wpa: 2d 76 12 f0 68 d6 36 44 b2 
D (64998) wpa: DPP: AES-SIV cleartext - hexdump(len=25):
D (64998) wpa: 05 10 10 00 0c fc 37 2f 56 14 8d 2e 3d e5 34 6b
D (65008) wpa: 74 4e 2e f9 06 10 01 00 02 
D (65008) wpa: DPP: I-nonce - hexdump(len=16):
D (65018) wpa: 0c fc 37 2f 56 14 8d 2e 3d e5 34 6b 74 4e 2e f9
D (65018) wpa: DPP: I-capabilities: 0x02
D (65028) wpa: DPP: Acting as Enrollee
D (65028) wpa: DPP: Build Authentication Response
D (65038) wpa: DPP: R-nonce - hexdump(len=16):
D (65038) wpa: f3 e7 c0 99 c3 ce 25 58 c4 e3 96 ab a0 47 3c f8
D (65288) wpa: DPP: Generating a keypair
E (65288) wpa: curve: secp256r1

E (65288) wpa: prime len is 32

E (65288) wpa: Q_x: - hexdump(len=32):
E (65298) wpa: 27 57 28 28 50 5c 1a a0 32 d2 b2 ba ac c4 24 9b
E (65298) wpa: f1 e5 87 a5 07 5c 3f 90 ce 43 6e 8a 89 eb eb 49 
E (65308) wpa: Q_y: - hexdump(len=32):
E (65308) wpa: 2b c3 e2 49 c8 08 4a 73 d1 ad f4 4d 90 54 40 6c
E (65318) wpa: 2f a1 32 50 a1 9e de 32 0a 11 c4 ed 61 9f 56 25 
E (65328) wpa: d:      - hexdump(len=32):
E (65328) wpa: c1 ec c8 73 ad 41 bf 26 37 2a a9 bf e5 9a d5 06 
E (65338) wpa: c1 f2 d3 81 0e 79 3c 8b dc d6 92 50 bd 1e 27 05
D (65588) wpa: DPP: ECDH shared secret (N.x) - hexdump(len=32):
D (65588) wpa: be 3d 4a 7a eb 32 19 3b 94 6a f7 70 66 d8 0c dc
D (65588) wpa: bc 32 0a 6f de 6f 70 4c 21 7b 6c 0f 42 2e 20 e8
D (65598) wpa: DPP: PRK = HKDF-Extract(<>, IKM=N.x) - hexdump(len=32):
D (65608) wpa: 4d 13 bb a1 f2 0a 4c 8d 51 0c 6c e1 7d cb f0 2c
D (65608) wpa: 65 b8 1e 4f 2c 67 06 46 bf b2 a5 0e e5 40 6f 27
D (65618) wpa: DPP: k2 = HKDF-Expand(PRK, info, L) - hexdump(len=32):
D (65618) wpa: ea 9f 7b 91 4c 0d d2 65 71 a5 29 9f a3 1f 05 ee
D (65628) wpa: 46 97 50 c3 18 32 1c 3d 1d 46 f7 d1 0f dd ef 76
D (65638) wpa: DPP: PRK = HKDF-Extract(<>, IKM) - hexdump(len=32):
D (65638) wpa: bb 7e e1 47 48 0f 02 d3 bc 1d 71 90 b8 cd 9d 73 
D (65648) wpa: b9 b1 3f 2a 34 cb 8a 67 f5 ae 43 ff f0 86 b0 7c
D (65648) wpa: DPP: ke = HKDF-Expand(PRK, info, L) - hexdump(len=32):
D (65658) wpa: ff d7 30 d0 7c 67 c5 a3 c3 bc da c9 f8 2a 6e 72 
D (65668) wpa: 16 76 98 2b d7 c7 1e bd 08 17 08 cb d9 9d 7a d5
D (65668) wpa: DPP: R-auth hash components
D (65678) wpa: DPP: hash component - hexdump(len=16):
D (65678) wpa: 0c fc 37 2f 56 14 8d 2e 3d e5 34 6b 74 4e 2e f9
D (65688) wpa: DPP: hash component - hexdump(len=16):
D (65688) wpa: f3 e7 c0 99 c3 ce 25 58 c4 e3 96 ab a0 47 3c f8 
D (65698) wpa: DPP: hash component - hexdump(len=32):
D (65698) wpa: 2e cc 68 18 67 c2 7a 7f d2 59 20 1f 89 c5 99 28 
D (65708) wpa: d2 59 3b 12 b9 07 13 4d 04 02 9a 80 0e 57 69 5c
D (65718) wpa: DPP: hash component - hexdump(len=32):
D (65718) wpa: 27 57 28 28 50 5c 1a a0 32 d2 b2 ba ac c4 24 9b 
D (65728) wpa: f1 e5 87 a5 07 5c 3f 90 ce 43 6e 8a 89 eb eb 49
D (65728) wpa: DPP: hash component - hexdump(len=32):
D (65738) wpa: c2 3f 6d 38 b9 ec 86 c0 75 d5 78 35 81 61 c4 1e 
D (65738) wpa: 5f 23 d3 3a a0 4d a1 fc 62 64 ce e5 ed a6 dc c3
D (65748) wpa: DPP: hash component - hexdump(len=1):
D (65758) wpa: 00
D (65758) wpa: DPP: R-auth - hexdump(len=32):
D (65758) wpa: 9c 68 7a de 49 3a fe 3d d4 e9 25 80 32 19 3b fe
D (65768) wpa: 43 2c 6c c1 ef c7 ae f2 c4 d6 eb 56 a0 e2 12 c2
D (65768) wpa: DPP: {R-auth}ke - hexdump(len=52):
D (65778) wpa: b6 59 c0 88 77 cc bf f5 4a 17 84 e6 56 44 cc f2
D (65778) wpa: 5c f9 89 67 ef 97 6e 43 94 a4 bb f4 46 2c a4 8b
D (65788) wpa: e2 4c 9c 5d 1c cd 0f 97 ae 80 d8 16 4e 3d ac 09
D (65798) wpa: 59 e9 4b 2e
D (65798) wpa: DPP: Status 0
D (65798) wpa: DPP: R-Bootstrap Key Hash
D (65808) wpa: DDP: AES-SIV AD[0] - hexdump(len=6):
D (65808) wpa: 50 6f 9a 1a 01 01
D (65808) wpa: DDP: AES-SIV AD[1] - hexdump(len=109):
D (65818) wpa: 00 10 01 00 00 02 10 20 00 d1 29 db 70 63 65 7c
D (65828) wpa: e0 a6 69 1d 0e 7b b4 2e c4 dc b0 9b f1 70 94 43
D (65828) wpa: b4 45 44 d9 d5 c2 50 90 a7 09 10 40 00 27 57 28 
D (65838) wpa: 28 50 5c 1a a0 32 d2 b2 ba ac c4 24 9b f1 e5 87
D (65838) wpa: a5 07 5c 3f 90 ce 43 6e 8a 89 eb eb 49 2b c3 e2
D (65848) wpa: 49 c8 08 4a 73 d1 ad f4 4d 90 54 40 6c 2f a1 32 
D (65858) wpa: 50 a1 9e de 32 0a 11 c4 ed 61 9f 56 25
D (65858) wpa: DPP: AES-SIV cleartext - hexdump(len=101):
D (65868) wpa: 07 10 10 00 f3 e7 c0 99 c3 ce 25 58 c4 e3 96 ab
D (65868) wpa: a0 47 3c f8 05 10 10 00 0c fc 37 2f 56 14 8d 2e
D (65878) wpa: 3d e5 34 6b 74 4e 2e f9 08 10 01 00 01 04 10 34 
D (65878) wpa: 00 b6 59 c0 88 77 cc bf f5 4a 17 84 e6 56 44 cc
D (65888) wpa: f2 5c f9 89 67 ef 97 6e 43 94 a4 bb f4 46 2c a4
D (65898) wpa: 8b e2 4c 9c 5d 1c cd 0f 97 ae 80 d8 16 4e 3d ac 
D (65898) wpa: 09 59 e9 4b 2e
D (65908) wpa: DPP: AES-SIV ciphertext - hexdump(len=117):
D (65908) wpa: 67 1e e0 44 0e 3e df b0 13 64 39 c7 17 84 df ff 
D (65918) wpa: 5d 44 24 40 0a 8e e8 55 8b e5 41 33 d2 13 75 19
D (65918) wpa: 53 0a f3 91 1b 4d 06 97 c7 d4 ac 95 29 2d 4a da
D (65928) wpa: f8 e2 1b a7 f5 69 a5 2a 26 5b f9 8f 6a cd a1 18 
D (65938) wpa: 3b 6f 8b 4f ed e4 15 f8 25 b0 c9 35 7f c6 15 bb
D (65938) wpa: d2 77 dc b9 33 9b 5b 73 5b 8c 81 8e 96 45 c9 08 
D (65948) wpa: d6 39 7c 20 90 4c 70 14 06 87 41 e0 96 3d 9e b7
D (65948) wpa: 5a 9e b1 4e 7e
D (65958) wpa: DPP: Authentication Response frame attributes - hexdump(len=238):
D (65958) wpa: 04 09 50 6f 9a 1a 01 01 00 10 01 00 00 02 10 20
D (65968) wpa: 00 d1 29 db 70 63 65 7c e0 a6 69 1d 0e 7b b4 2e 
D (65978) wpa: c4 dc b0 9b f1 70 94 43 b4 45 44 d9 d5 c2 50 90
D (65978) wpa: a7 09 10 40 00 27 57 28 28 50 5c 1a a0 32 d2 b2
D (65988) wpa: ba ac c4 24 9b f1 e5 87 a5 07 5c 3f 90 ce 43 6e
D (65988) wpa: 8a 89 eb eb 49 2b c3 e2 49 c8 08 4a 73 d1 ad f4
D (65998) wpa: 4d 90 54 40 6c 2f a1 32 50 a1 9e de 32 0a 11 c4
D (66008) wpa: ed 61 9f 56 25 04 10 75 00 67 1e e0 44 0e 3e df
D (66008) wpa: b0 13 64 39 c7 17 84 df ff 5d 44 24 40 0a 8e e8
D (66018) wpa: 55 8b e5 41 33 d2 13 75 19 53 0a f3 91 1b 4d 06
D (66018) wpa: 97 c7 d4 ac 95 29 2d 4a da f8 e2 1b a7 f5 69 a5
D (66028) wpa: 2a 26 5b f9 8f 6a cd a1 18 3b 6f 8b 4f ed e4 15
D (66038) wpa: f8 25 b0 c9 35 7f c6 15 bb d2 77 dc b9 33 9b 5b
D (66038) wpa: 73 5b 8c 81 8e 96 45 c9 08 d6 39 7c 20 90 4c 70
D (66048) wpa: 14 06 87 41 e0 96 3d 9e b7 5a 9e b1 4e 7e
D (66048) wpa: DPP: Mgmt Tx - MAC:ac:3e:b1:02:80:e0, Channel-6, WaitT-500        
D (66138) event: running post WIFI_EVENT:19 with handler 0x400d6adc and context 0x3ffbdcfc on loop 0x3ffbc9f0
0x400d6adc: event_handler(void*, char const*, int, void*) at C:/Users/Alma/sensor-data-update/main/main.cpp:55

D (66138) event: running post WIFI_EVENT:19 with handler 0x400e0420 and context 0x3ffcf020 on loop 0x3ffbc9f0
0x400e0420: offchan_event_handler at C:/Users/Alma/esp443/esp-idf/components/wpa_supplicant/esp_supplicant/src/esp_dpp.c:449

D (66148) wpa: Mgmt Tx Status - 1, Cookie - 0x400e036c
0x400e036c: esp_supp_rx_action at C:/Users/Alma/esp443/esp-idf/components/wpa_supplicant/esp_supplicant/src/esp_dpp.c:413

I (66148) wifi dpp-enrollee: DPP Auth failed (Reason: ESP_ERR_DPP_TX_FAILURE), retry...
D (66658) event: running post WIFI_EVENT:20 with handler 0x400d6adc and context 0x3ffbdcfc on loop 0x3ffbc9f0
0x400d6adc: event_handler(void*, char const*, int, void*) at C:/Users/Alma/sensor-data-update/main/main.cpp:55

D (66658) event: running post WIFI_EVENT:20 with handler 0x400e0420 and context 0x3ffcf050 on loop 0x3ffbc9f0
0x400e0420: offchan_event_handler at C:/Users/Alma/esp443/esp-idf/components/wpa_supplicant/esp_supplicant/src/esp_dpp.c:449

More Information.

Seems afterwards it crashes Wi-Fi module.

[knight-ryu12]

Update on this:
if, LWIP Enable reassembly incoming fragmented IP4 packets are enabled, above example will not work. if disabled, it suddenly work now.

Hmm.

[jasta]

I'm having the same issue (dpp-enrollee yields ESP_ERR_DPP_TX_FAILURE). For me it is strangely persistent but unpredictable. That is, I've had it work correctly in the past, but somehow once a given device gets into this state it will yield this error over and over no matter what I do, even if I reset the flash. I believe @knight-ryu12 is describing something similar where a seemingly unrelated change "fixed it". Looks like others have also experienced this: https://esp32.com/viewtopic.php?t=28573.

Needless to say this unpredictability makes it impossible to actually ship something that uses DPP, so we need to find some predictable way of detecting and working around this condition.

For reference, my ESP32-C3-DevKit-M1U is working, my ESP32-C3-DevKit-M1 isn't. Both are using v4.4.4.

[kapilkedawat]

Hi @jasta , we are trying to reproduce it locally. Are you using the example?

Please share your sdkconfig as well as IDF version commit.

[jasta]

Yes, I'm able to reproduce consistently with the unmodified example on the current v4.4.4 tag of esp-idf. I am using the default settings (channel 6, no provided key/device info). Here's the sdkconfig: https://gist.github.com/42ef0f07990ca812bba8b541685ef798

[jasta]

The bug really smells like a race condition IMO. I had it all working perfectly and changed nothing of significance about my app and it just started giving me ESP_ERR_DPP_TX_FAILURE over and over. Then no amount of reverting my code could fix it, including reverting all the way back to the unmodified example which is where I started. It of course used to work with the sample and even my considerably more robust full app. I suspect that the "condition" that changes to cause it to become persistently broken is literally in the air -- something about my Wi-Fi setup must be able to consistently reproduce an "unlikely" race condition outcome.

No hardware has been deliberately modified or replaced since it was once working, so the only possibilities in my view are environmental (wireless signals themselves changing) or through automated software updates of either my router (Google WiFi infrastructure) or my phone (Android Pixel 6)

[jasta]

Well that's interesting, even though I get ESP_ERR_DPP_TX_FAILURE pretty much every time, I now just got ESP_ERR_DPP_INVALID_ATTR. Adds quite a bit of evidence to my theory that this is a race :)

I swear it is seeming like the difference between the two errors is whether I have the esp32 on my desk (DPP_INVALID_ATTR) or in my component drawer (DPP_TX_FAILURE). Bizarre :)

[jasta]

As an aside, I am the one working on adding DPP support to Rust and ran into this issue maturing the implementation even though I didn't change anything functionally interesting with respect to esp_* calls: esp-rs/esp-idf-svc#228 .

[jasta]

I have logs with the full debugging turned up but I'm not posting here as I believe they will contain my Wi-Fi creds. Lmk and I can share them privately or reproduce with a dummy network (though I suspect changing my network around will change the results)

[kapilkedawat]

I have logs with the full debugging turned up but I'm not posting here as I believe they will contain my Wi-Fi creds. Lmk and I can share them privately or reproduce with a dummy network (though I suspect changing my network around will change the results)

Please black out wifi cred from the logs and share the rest.

[jasta]

I can't actually tell what is and isn't sensitive about this, but I'm interested enough in getting this solved that I'll risk it hehe: https://gist.github.com/09fe320e7b549967b37088170e59c5cb. Here is the updated sdkconfig after I enabled logging: https://gist.github.com/8ab02d9c9ca064861e9e1cdf22261545

I confirmed again this morning it still repros. I seemingly have a 100% reliable repro (it's happened at least the last 20 or 30 times I've tried) on a devkit module that once worked just fine. One maybe important detail though is that in the example I'm unable to scan the QR code in the console (my phone never recognizes it at as a QR code), so I'm copying the QR text into qtqr and generating one there. I can confirm that if I fudge the QR text I get a different error ("No matching own bootstrapping key found as responder - ignoring message"), and then it yields ESP_ERR_DPP_INVALID_ATTR (different than the INVALID_ATTR case I got when I was randomly moving the device around physically).

[knight-ryu12]

I don't know for sure, but it crashes Wi-Fi event handler hardly afterwards. I cannot receive any events after DPP had failed. I assume that might have to do with how LWIP is handling packets? (Or is it just my condition being bad...)