espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.49k stars 7.26k forks source link

Example esp-idf-examples-protocols-mqtt-ssl_mutual_auth fails (IDFGH-10171) #11440

Closed diplfranzhoepfinger closed 1 year ago

diplfranzhoepfinger commented 1 year ago

Answers checklist.

IDF version.

v5.0.2

Operating System used.

Linux

How did you build your project?

Eclipse IDE

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

None

Development Kit.

ESP32-S3-DevKitC

Power Supply used.

USB

What is the expected behavior?

I expected it to connect

What is the actual behavior?

see Logs.

Steps to reproduce.

See this Project: https://github.com/diplfranzhoepfinger/esp-idf-examples-protocols-mqtt-ssl_mutual_auth/tree/feature/1

Debug Logs.

--- idf_monitor on /dev/ttyUSB0 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
Octal Flash Mode Enabled
For OPI Flash, Use Default Flash Boot Mode
mode:SLOW_RD, clock div:1
load:0x3fce3810,len:0x1658
load:0x403c9700,len:0xbe0
load:0x403cc700,len:0x2d9c
entry 0x403c9900
I (32) boot: ESP-IDF v5.0.2 2nd stage bootloader
I (32) boot: compile time 10:15:30
I (32) boot: chip revision: v0.1
I (34) boot.esp32s3: Boot SPI Speed : 80MHz
I (39) boot.esp32s3: SPI Mode       : SLOW READ
I (44) boot.esp32s3: SPI Flash Size : 2MB
I (49) boot: Enabling RNG early entropy source...
I (54) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (72) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (80) boot:  2 factory          factory app      00 00 00010000 00177000
I (87) boot: End of partition table
I (91) esp_image: segment 0: paddr=00010020 vaddr=3c0a0020 size=257f8h (153592) map
I (136) esp_image: segment 1: paddr=00035820 vaddr=3fc96800 size=03e34h ( 15924) load
I (141) esp_image: segment 2: paddr=0003965c vaddr=40374000 size=069bch ( 27068) load
I (149) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=90b30h (592688) map
I (290) esp_image: segment 4: paddr=000d0b58 vaddr=4037a9bc size=0be0ch ( 48652) load
I (311) boot: Loaded app from partition at offset 0x10000
I (311) boot: Disabling RNG early entropy source...
I (323) cpu_start: Pro cpu up.
I (323) cpu_start: Starting app cpu, entry point is 0x4037539c
0x4037539c: call_start_cpu1 at /home/franz/esp-idf-v5.0.2/components/esp_system/port/cpu_start.c:141

I (0) cpu_start: App cpu up.
I (338) cpu_start: Pro cpu start user code
I (338) cpu_start: cpu freq: 160000000 Hz
I (338) cpu_start: Application information:
I (341) cpu_start: Project name:     mqtt_ssl_mutual_auth
I (347) cpu_start: App version:      d9aeddf
I (352) cpu_start: Compile time:     May 19 2023 10:17:35
I (358) cpu_start: ELF file SHA256:  71ac5b0322fd6719...
I (364) cpu_start: ESP-IDF:          v5.0.2
I (369) cpu_start: Min chip rev:     v0.0
I (373) cpu_start: Max chip rev:     v0.99 
I (378) cpu_start: Chip rev:         v0.1
I (383) heap_init: Initializing. RAM available for dynamic allocation:
I (390) heap_init: At 3FC9E6C8 len 0004B048 (300 KiB): DRAM
I (396) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (403) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (409) heap_init: At 600FE010 len 00001FF0 (7 KiB): RTCRAM
I (417) spi_flash: detected chip: mxic
W (420) spi_flash: Detected flash size > 16 MB, but access beyond 16 MB is not supported for this flash model yet.
I (431) spi_flash: flash io: dio
W (435) spi_flash: Detected size(32768k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (449) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (469) MQTTS_EXAMPLE: [APP] Startup..
I (469) MQTTS_EXAMPLE: [APP] Free memory: 348272 bytes
I (479) MQTTS_EXAMPLE: [APP] IDF version: v5.0.2
I (489) example_connect: Start example_connect.
I (489) pp: pp rom version: e7ae62f
I (489) net80211: net80211 rom version: e7ae62f
I (519) wifi:wifi driver task: 3fca836c, prio:23, stack:6656, core=0
I (519) system_api: Base MAC address is not set
I (519) system_api: read default base MAC address from EFUSE
I (529) wifi:wifi firmware version: 57982fe
I (529) wifi:wifi certification version: v7.0
I (529) wifi:config NVS flash: enabled
I (529) wifi:config nano formating: disabled
I (539) wifi:Init data frame dynamic rx buffer num: 32
I (539) wifi:Init management frame dynamic rx buffer num: 32
I (549) wifi:Init management short buffer num: 32
I (549) wifi:Init dynamic tx buffer num: 32
I (559) wifi:Init static tx FG buffer num: 2
I (559) wifi:Init static rx buffer size: 1600
I (559) wifi:Init static rx buffer num: 10
I (569) wifi:Init dynamic rx buffer num: 32
I (569) wifi_init: rx ba win: 6
I (579) wifi_init: tcpip mbox: 32
I (579) wifi_init: udp mbox: 6
I (579) wifi_init: tcp mbox: 6
I (589) wifi_init: tcp tx win: 5744
I (589) wifi_init: tcp rx win: 5744
I (599) wifi_init: tcp mss: 1440
I (599) wifi_init: WiFi IRAM OP enabled
I (599) wifi_init: WiFi RX IRAM OP enabled
I (609) phy_init: phy_version 540,a5d905b,Oct 20 2022,19:36:11
W (619) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
I (659) wifi:mode : sta (68:b6:b3:3e:17:a8)
I (669) wifi:enable tsf
I (669) example_connect: Connecting to devolo-guest-644...
I (669) example_connect: Waiting for IP(s)
I (3079) wifi:new:<11,2>, old:<1,0>, ap:<255,255>, sta:<11,2>, prof:1
I (3079) wifi:state: init -> auth (b0)
I (4129) wifi:state: auth -> assoc (0)
E (4149) wifi:Association refused temporarily, comeback time 1017 mSec
I (5169) wifi:state: assoc -> assoc (0)
I (6169) wifi:state: assoc -> init (200)
I (6169) wifi:new:<11,0>, old:<11,2>, ap:<255,255>, sta:<11,2>, prof:1
I (6169) example_connect: Wi-Fi disconnected, trying to reconnect...
I (8589) example_connect: Wi-Fi disconnected, trying to reconnect...
I (10999) wifi:new:<11,2>, old:<11,0>, ap:<255,255>, sta:<11,2>, prof:1
I (10999) wifi:state: init -> auth (b0)
I (12019) wifi:state: auth -> assoc (0)
I (12029) wifi:state: assoc -> run (10)
I (12069) wifi:connected with devolo-guest-644, aid = 1, channel 11, 40D, bssid = be:be:f4:a6:be:f4
I (12069) wifi:security: WPA3-SAE, phy: bgn, rssi: -41
I (12079) wifi:pm start, type: 1

I (12079) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 0, mt_pti: 25000, mt_time: 10000
I (12099) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (12109) wifi:<ba-add>idx:0 (ifx:0, be:be:f4:a6:be:f4), tid:6, ssn:2, winSize:64
I (13089) esp_netif_handlers: example_netif_sta ip: 192.168.178.143, mask: 255.255.255.0, gw: 192.168.178.1
I (13089) example_connect: Got IPv4 event: Interface "example_netif_sta" address: 192.168.178.143
I (13489) example_connect: Got IPv6 event: Interface "example_netif_sta" address: fe80:0000:0000:0000:6ab6:b3ff:fe3e:17a8, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (13489) example_common: Connected to example_netif_sta
I (13499) example_common: - IPv4 address: 192.168.178.143,
I (13499) wifi:<ba-add>idx:1 (ifx:0, be:be:f4:a6:be:f4), tid:0, ssn:0, winSize:64
I (13509) example_common: - IPv6 address: fe80:0000:0000:0000:6ab6:b3ff:fe3e:17a8, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (13519) MQTTS_EXAMPLE: [APP] Free memory: 301660 bytes
I (13529) MQTTS_EXAMPLE: Other event id:7
E (13589) esp-tls-mbedtls: mbedtls_x509_crt_parse returned -0x2180
E (13589) esp-tls-mbedtls: Failed to set client pki context
E (13589) esp-tls-mbedtls: Failed to set client configurations, returned [0x8015] (ESP_ERR_MBEDTLS_X509_CRT_PARSE_FAILED)
E (13599) esp-tls: create_ssl_handle failed
E (13609) esp-tls: Failed to open new connection
E (13609) transport_base: Failed to open a new connection
E (13619) mqtt_client: Error transport connect
I (13629) MQTTS_EXAMPLE: MQTT_EVENT_ERROR
E (13629) MQTTS_EXAMPLE: Last error reported from esp-tls: 0x8015
E (13639) MQTTS_EXAMPLE: Last error reported from tls stack: 0x2180
I (13639) MQTTS_EXAMPLE: Last errno string (Success)
I (13649) MQTTS_EXAMPLE: MQTT_EVENT_DISCONNECTED
I (28649) MQTTS_EXAMPLE: Other event id:7
E (28679) esp-tls-mbedtls: mbedtls_x509_crt_parse returned -0x2180
E (28689) esp-tls-mbedtls: Failed to set client pki context
E (28689) esp-tls-mbedtls: Failed to set client configurations, returned [0x8015] (ESP_ERR_MBEDTLS_X509_CRT_PARSE_FAILED)
E (28699) esp-tls: create_ssl_handle failed
E (28699) esp-tls: Failed to open new connection
E (28709) transport_base: Failed to open a new connection
E (28719) mqtt_client: Error transport connect
I (28719) MQTTS_EXAMPLE: MQTT_EVENT_ERROR
E (28719) MQTTS_EXAMPLE: Last error reported from esp-tls: 0x8015
E (28729) MQTTS_EXAMPLE: Last error reported from tls stack: 0x2180
I (28739) MQTTS_EXAMPLE: Last errno string (Success)
I (28739) MQTTS_EXAMPLE: MQTT_EVENT_DISCONNECTED

More Information.

No response

diplfranzhoepfinger commented 1 year ago

Code used: https://github.com/espressif/esp-idf/tree/v5.0.2/examples/protocols/mqtt/ssl_mutual_auth

diplfranzhoepfinger commented 1 year ago

ahhhhhh

https://github.com/espressif/esp-idf/tree/v5.0.2/examples/protocols/mqtt/ssl_mutual_auth#configure-the-project

RTFM

i will try !!!

diplfranzhoepfinger commented 1 year ago

working:

--- idf_monitor on /dev/ttyUSB0 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
Octal Flash Mode Enabled
For OPI Flash, Use Default Flash Boot Mode
mode:SLOW_RD, clock div:1
load:0x3fce3810,len:0x1658
load:0x403c9700,len:0xbe0
load:0x403cc700,len:0x2d9c
entry 0x403c9900
I (32) boot: ESP-IDF v5.0.2 2nd stage bootloader
I (32) boot: compile time 10:15:30
I (32) boot: chip revision: v0.1
I (34) boot.esp32s3: Boot SPI Speed : 80MHz
I (39) boot.esp32s3: SPI Mode       : SLOW READ
I (44) boot.esp32s3: SPI Flash Size : 2MB
I (49) boot: Enabling RNG early entropy source...
I (54) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (72) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (80) boot:  2 factory          factory app      00 00 00010000 00177000
I (87) boot: End of partition table
I (91) esp_image: segment 0: paddr=00010020 vaddr=3c0a0020 size=26388h (156552) map
I (137) esp_image: segment 1: paddr=000363b0 vaddr=3fc96800 size=03e34h ( 15924) load
I (141) esp_image: segment 2: paddr=0003a1ec vaddr=40374000 size=05e2ch ( 24108) load
I (149) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=90b30h (592688) map
I (290) esp_image: segment 4: paddr=000d0b58 vaddr=40379e2c size=0c99ch ( 51612) load
I (313) boot: Loaded app from partition at offset 0x10000
I (313) boot: Disabling RNG early entropy source...
I (324) cpu_start: Pro cpu up.
I (324) cpu_start: Starting app cpu, entry point is 0x4037539c
0x4037539c: call_start_cpu1 at /home/franz/esp-idf-v5.0.2/components/esp_system/port/cpu_start.c:141

I (0) cpu_start: App cpu up.
I (339) cpu_start: Pro cpu start user code
I (339) cpu_start: cpu freq: 160000000 Hz
I (339) cpu_start: Application information:
I (342) cpu_start: Project name:     mqtt_ssl_mutual_auth
I (348) cpu_start: App version:      e9eb30c
I (353) cpu_start: Compile time:     May 19 2023 10:35:09
I (359) cpu_start: ELF file SHA256:  239646345f1f67c9...
I (365) cpu_start: ESP-IDF:          v5.0.2
I (370) cpu_start: Min chip rev:     v0.0
I (375) cpu_start: Max chip rev:     v0.99 
I (380) cpu_start: Chip rev:         v0.1
I (385) heap_init: Initializing. RAM available for dynamic allocation:
I (392) heap_init: At 3FC9E6C8 len 0004B048 (300 KiB): DRAM
I (398) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (405) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (411) heap_init: At 600FE010 len 00001FF0 (7 KiB): RTCRAM
I (419) spi_flash: detected chip: mxic
W (422) spi_flash: Detected flash size > 16 MB, but access beyond 16 MB is not supported for this flash model yet.
I (433) spi_flash: flash io: dio
W (437) spi_flash: Detected size(32768k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (451) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (471) MQTTS_EXAMPLE: [APP] Startup..
I (471) MQTTS_EXAMPLE: [APP] Free memory: 348272 bytes
I (481) MQTTS_EXAMPLE: [APP] IDF version: v5.0.2
I (491) example_connect: Start example_connect.
I (491) pp: pp rom version: e7ae62f
I (491) net80211: net80211 rom version: e7ae62f
I (521) wifi:wifi driver task: 3fca836c, prio:23, stack:6656, core=0
I (521) system_api: Base MAC address is not set
I (521) system_api: read default base MAC address from EFUSE
I (531) wifi:wifi firmware version: 57982fe
I (531) wifi:wifi certification version: v7.0
I (531) wifi:config NVS flash: enabled
I (531) wifi:config nano formating: disabled
I (541) wifi:Init data frame dynamic rx buffer num: 32
I (541) wifi:Init management frame dynamic rx buffer num: 32
I (551) wifi:Init management short buffer num: 32
I (551) wifi:Init dynamic tx buffer num: 32
I (561) wifi:Init static tx FG buffer num: 2
I (561) wifi:Init static rx buffer size: 1600
I (561) wifi:Init static rx buffer num: 10
I (571) wifi:Init dynamic rx buffer num: 32
I (571) wifi_init: rx ba win: 6
I (581) wifi_init: tcpip mbox: 32
I (581) wifi_init: udp mbox: 6
I (581) wifi_init: tcp mbox: 6
I (591) wifi_init: tcp tx win: 5744
I (591) wifi_init: tcp rx win: 5744
I (601) wifi_init: tcp mss: 1440
I (601) wifi_init: WiFi IRAM OP enabled
I (601) wifi_init: WiFi RX IRAM OP enabled
I (611) phy_init: phy_version 540,a5d905b,Oct 20 2022,19:36:11
W (621) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
I (661) wifi:mode : sta (68:b6:b3:3e:17:a8)
I (671) wifi:enable tsf
I (671) example_connect: Connecting to devolo-guest-644...
I (671) example_connect: Waiting for IP(s)
I (3081) wifi:new:<11,2>, old:<1,0>, ap:<255,255>, sta:<11,2>, prof:1
I (3081) wifi:state: init -> auth (b0)
I (4121) wifi:state: auth -> assoc (0)
E (4141) wifi:Association refused temporarily, comeback time 1017 mSec
I (5161) wifi:state: assoc -> assoc (0)
I (6161) wifi:state: assoc -> init (200)
I (6161) wifi:new:<11,0>, old:<11,2>, ap:<255,255>, sta:<11,2>, prof:1
I (6161) example_connect: Wi-Fi disconnected, trying to reconnect...
I (8581) example_connect: Wi-Fi disconnected, trying to reconnect...
I (10981) wifi:new:<11,2>, old:<11,0>, ap:<255,255>, sta:<11,2>, prof:1
I (10991) wifi:state: init -> auth (b0)
I (11791) wifi:state: auth -> assoc (0)
I (11811) wifi:state: assoc -> run (10)
I (11841) wifi:connected with devolo-guest-644, aid = 1, channel 11, 40D, bssid = be:be:f4:a6:be:f4
I (11851) wifi:security: WPA3-SAE, phy: bgn, rssi: -42
I (11851) wifi:pm start, type: 1

I (11851) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 0, mt_pti: 25000, mt_time: 10000
I (11871) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (11881) wifi:<ba-add>idx:0 (ifx:0, be:be:f4:a6:be:f4), tid:6, ssn:2, winSize:64
I (12861) esp_netif_handlers: example_netif_sta ip: 192.168.178.143, mask: 255.255.255.0, gw: 192.168.178.1
I (12861) example_connect: Got IPv4 event: Interface "example_netif_sta" address: 192.168.178.143
I (13491) example_connect: Got IPv6 event: Interface "example_netif_sta" address: fe80:0000:0000:0000:6ab6:b3ff:fe3e:17a8, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (13491) example_common: Connected to example_netif_sta
I (13501) example_common: - IPv4 address: 192.168.178.143,
I (13501) wifi:<ba-add>idx:1 (ifx:0, be:be:f4:a6:be:f4), tid:0, ssn:0, winSize:64
I (13511) example_common: - IPv6 address: fe80:0000:0000:0000:6ab6:b3ff:fe3e:17a8, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (13521) MQTTS_EXAMPLE: [APP] Free memory: 301684 bytes
I (13531) MQTTS_EXAMPLE: Other event id:7
I (14671) MQTTS_EXAMPLE: MQTT_EVENT_CONNECTED
I (14681) MQTTS_EXAMPLE: sent subscribe successful, msg_id=12995
I (14681) MQTTS_EXAMPLE: sent subscribe successful, msg_id=44436
I (14681) MQTTS_EXAMPLE: sent unsubscribe successful, msg_id=24920
I (14711) MQTTS_EXAMPLE: MQTT_EVENT_SUBSCRIBED, msg_id=12995
I (14711) MQTTS_EXAMPLE: sent publish successful, msg_id=0
I (14741) MQTTS_EXAMPLE: MQTT_EVENT_SUBSCRIBED, msg_id=44436
I (14741) MQTTS_EXAMPLE: sent publish successful, msg_id=0
I (14751) MQTTS_EXAMPLE: MQTT_EVENT_UNSUBSCRIBED, msg_id=24920
I (14771) MQTTS_EXAMPLE: MQTT_EVENT_DATA
TOPIC=/topic/qos0
DATA=data
I (14801) MQTTS_EXAMPLE: MQTT_EVENT_DATA
TOPIC=/topic/qos0
DATA=data