search

Infineon / azure-optiga-trust-m

Microsoft Azure IoT with OPTIGA™ Trust M
MIT License
2 stars 0 forks source link

SCL, SDA, RST configuration #1

Open ayushev opened 3 years ago

ayushev commented 3 years ago

I am also following #34 to test a working example azure-optga-trust-m provision_test_certificate. I was able to successfully build the code for esp32-s2 but I could not figure out where to provide GPIO numbers for SCL, SDA and RST as I have different GPIOs allocated for I2C.

Originally posted by @markandpathak in https://github.com/Infineon/optiga-trust-m/issues/64#issuecomment-867866280

ayushev commented 3 years ago

if you have the components folder with optiga in place (the respo is cloned recusivly) then you should be able to see an extra menu under the "components" menu when you execute idf.py menuconfig Do you see it there? For instance a new certificate creation is describe in this menu with screenshots

markandpathak commented 3 years ago

I selected the certificate slot as given in the screenshots but there is no option to change the hardware pins in the menuconfig.

ayushev commented 3 years ago

you are right, becasue it is prepared for a specific board, could you try this Kconfig.zip (you need to unzip it) and place it here and replace the original file. You should now see the new menu under the same component.

markandpathak commented 3 years ago

Ok. I will check with the new Kconfig. I will not be having access to the hardware this weekend. I'll test it and update it here on monday.

markandpathak commented 3 years ago

Hello @ayushev , I tried as you suggested. I have set the SCL, SDA and RST pins. Although I am getting some I2C frequency error. The error is before pal_i2c_init successful message. And then I think it is going into some loop depriving other tasks of CPU time hence watch-dog timer gets triggered. I also tried on a clean pull from repo, same error. 

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x1830
load:0x4004c000,len:0x9e8
load:0x40050000,len:0x2b70
SHA-256 comparison failed:
Calculated: 2947ce8b4c88197179d5ec8c64f0c29dfad2b322e4eae0bb6a37a24d5c643ae3
Expected: d4c2f6ffac54f5c6e7382590e317dd1f4bb7493a3174122667d86dd7c1108686
Attempting to boot anyway...
entry 0x4004c1ec
I (40) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (40) boot: compile time 15:29:58
I (40) boot: chip revision: 0
I (43) boot.esp32s2: SPI Speed      : 80MHz
I (47) boot.esp32s2: SPI Mode       : DIO
I (52) boot.esp32s2: SPI Flash Size : 4MB
I (57) boot: Enabling RNG early entropy source...
I (62) boot: Partition Table:
I (66) boot: ## Label            Usage          Type ST Offset   Length
I (73) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (81) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (88) boot:  2 factory          factory app      00 00 00010000 00100000
I (95) boot: End of partition table
I (100) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=08d60h ( 36192) map
I (116) esp_image: segment 1: paddr=00018d88 vaddr=3ffbe430 size=02cd4h ( 11476) load
I (119) esp_image: segment 2: paddr=0001ba64 vaddr=40022000 size=045b4h ( 17844) load
I (130) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=1b910h (112912) map
I (158) esp_image: segment 4: paddr=0003b938 vaddr=400265b4 size=07e74h ( 32372) load
I (167) esp_image: segment 5: paddr=000437b4 vaddr=50000000 size=00010h (    16) load
I (174) boot: Loaded app from partition at offset 0x10000
I (174) boot: Disabling RNG early entropy source...
I (189) cac��f<��3?����f],]Z�
                             �V�,ZY�B��size 8KB, 4Ways, cache line size 32Byte
I (189) cpu_start: Pro cpu up.
I (200) cpu_start: Pro cpu start user code
I (200) cpu_start: cpu freq: 160000000
I (201) cpu_start: Application information:
I (205) cpu_start: Project name:     provision_test_certificate
I (212) cpu_start: App version:      202005.00-3-g722bb54-dirty
I (218) cpu_start: Compile time:     Jun 28 2021 15:29:52
I (224) cpu_start: ELF file SHA256:  e8bc9c780a21f3e0...
I (230) cpu_start: ESP-IDF:          v4.3-dirty
I (236) heap_init: Initializing. RAM available for dynamic allocation:
I (243) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (249) heap_init: At 3FFC20D8 len 00039F28 (231 KiB): DRAM
I (255) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (262) spi_flash: detected chip: generic
I (266) spi_flash: flash io: dio
I (271) cpu_start: Starting scheduler on PRO CPU.
I (476) pal_os_event: Init : Create Timer
I (476) pal_os_event: Init : Create Timer successful
I (546) pal_i2c: Initialize pal_i2c_init  
E (546) i2c: i2c_param_config(645): i2c clock choice is invalid, please check flag and frequency
I (546) pal_i2c: init successful
E (5456) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (5456) task_wdt:  - IDLE (CPU 0)
E (5456) task_wdt: Tasks currently running:
E (5456) task_wdt: CPU 0: main
E (5456) task_wdt: Print CPU 0 (current core) backtrace

Backtrace:0x4008CC66:0x3FFBEBD0 0x400240EE:0x3FFBEBF0 0x40086B6D:0x3FFC3730 0x40086AC7:0x3FFC3750 0x4009B75E:0x3FFC3770 0x4002A61D:0x3FFC3790 
0x4008cc66: task_wdt_isr at /home/invesun/esp/esp-idf/components/esp_common/src/task_wdt.c:189

0x400240ee: _xt_lowint1 at /home/invesun/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1105

0x40086b6d: optiga_trust_init at /home/invesun/UNITGRID/optiga/azure-optiga-trust-m/components/optiga/optiga-trust-m/examples/utilities/optiga_trust.c:599

0x40086ac7: app_main at /home/invesun/UNITGRID/optiga/azure-optiga-trust-m/examples/provision_test_certificate/build/../main/main.c:409

0x4009b75e: main_task at /home/invesun/esp/esp-idf/components/freertos/port/port_common.c:133 (discriminator 2)

0x4002a61d: vPortTaskWrapper at /home/invesun/esp/esp-idf/components/freertos/port/xtensa/port.c:168

E (10456) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (10456) task_wdt:  - IDLE (CPU 0)
E (10456) task_wdt: Tasks currently running:
E (10456) task_wdt: CPU 0: main
E (10456) task_wdt: Print CPU 0 (current core) backtrace

Backtrace:0x4008CC66:0x3FFBEBD0 0x400240EE:0x3FFBEBF0 0x40086B6D:0x3FFC3730 0x40086AC7:0x3FFC3750 0x4009B75E:0x3FFC3770 0x4002A61D:0x3FFC3790 
0x4008cc66: task_wdt_isr at /home/invesun/esp/esp-idf/components/esp_common/src/task_wdt.c:189

0x400240ee: _xt_lowint1 at /home/invesun/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1105

0x40086b6d: optiga_trust_init at /home/invesun/UNITGRID/optiga/azure-optiga-trust-m/components/optiga/optiga-trust-m/examples/utilities/optiga_trust.c:599

0x40086ac7: app_main at /home/invesun/UNITGRID/optiga/azure-optiga-trust-m/examples/provision_test_certificate/build/../main/main.c:409

0x4009b75e: main_task at /home/invesun/esp/esp-idf/components/freertos/port/port_common.c:133 (discriminator 2)

0x4002a61d: vPortTaskWrapper at /home/invesun/esp/esp-idf/components/freertos/port/xtensa/port.c:168
markandpathak commented 3 years ago

@ayushev I tried the code with different I2C speeds but no luck. Same error.

ayushev commented 3 years ago

@markandpathak I noticed you use a different from mentioned here ESP IDF version, in the 4.3 the i2c driver is abit different, could you please return back the original settings and add this line conf.clk_flags = 0; somewhere here

markandpathak commented 3 years ago

Yes, I also referred to same clk_flags settings after some research. I modified in pal_i2c.c and it worked. Now it's stuck at Writing to Oid : E0E1. I tried to reset several times but same it gets stuck at the same point. The output is:

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x1830
load:0x4004c000,len:0x9e8
load:0x40050000,len:0x2b70
entry 0x4004c1ec
I (21) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (21) boot: compile time 12:10:18
I (21) boot: chip revision: 0
I (24) boot.esp32s2: SPI Speed      : 80MHz
I (29) boot.esp32s2: SPI Mode       : DIO
I (34) boot.esp32s2: SPI Flash Size : 4MB
I (38) boot: Enabling RNG early entropy source...
I (44) boot: Partition Table:
I (47) boot: ## Label            Usage          Type ST Offset   Length
I (55) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (62) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (70) boot:  2 factory          factory app      00 00 00010000 00100000
I (77) boot: End of partition table
I (81) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=08d60h ( 36192) map
I (98) esp_image: segment 1: paddr=00018d88 vaddr=3ffbe430 size=02cd4h ( 11476) load
I (101) esp_image: segment 2: paddr=0001ba64 vaddr=40022000 size=045b4h ( 17844) load
I (111) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=1b914h (112916) map
I (139) esp_image: segment 4: paddr=0003b93c vaddr=400265b4 size=07e74h ( 32372) load
I (148) esp_image: segment 5: paddr=000437b8 vaddr=50000000 size=00010h (    16) load
I (155) boot: Loaded app from partition at offset 0x10000
I (155) boot: Disabling RNG early entropy source...
I (170) ca��fÆ~
               ��3?����W�,W��
                             �V�,ZY�B��size 8KB, 4Ways, cache line size 32Byte
I (170) cpu_start: Pro cpu up.
I (182) cpu_start: Pro cpu start user code
I (182) cpu_start: cpu freq: 160000000
I (182) cpu_start: Application information:
I (187) cpu_start: Project name:     provision_test_certificate
I (193) cpu_start: App version:      202005.00-3-g722bb54-dirty
I (200) cpu_start: Compile time:     Jul  2 2021 12:10:13
I (206) cpu_start: ELF file SHA256:  1bcd041309bbc8ee...
I (212) cpu_start: ESP-IDF:          v4.3-dirty
I (217) heap_init: Initializing. RAM available for dynamic allocation:
I (224) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (230) heap_init: At 3FFC20D8 len 00039F28 (231 KiB): DRAM
I (237) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (243) spi_flash: detected chip: generic
I (248) spi_flash: flash io: dio
I (252) cpu_start: Starting scheduler on PRO CPU.
I (457) pal_os_event: Init : Create Timer
I (457) pal_os_event: Init : Create Timer successful
I (527) pal_i2c: Initialize pal_i2c_init  
I (527) pal_i2c: init successful

 30 82 01 A1 30 82 01 47 02 09 00 DA 1B 1B EA 7D
 2F 17 56 30 0A 06 08 2A 86 48 CE 3D 04 03 02 30
 59 31 0B 30 09 06 03 55 04 06 13 02 49 4E 31 0C
 30 0A 06 03 55 04 08 0C 03 4B 41 52 31 0D 30 0B
 06 03 55 04 07 0C 04 42 41 4E 47 31 0D 30 0B 06
 03 55 04 0A 0C 04 49 46 49 4E 31 0C 30 0A 06 03
 55 04 0B 0C 03 44 53 53 31 10 30 0E 06 03 55 04
 03 0C 07 41 7A 75 72 65 43 41 30 1E 17 0D 32 30
 30 37 31 32 31 31 30 36 34 31 5A 17 0D 32 31 31
 31 32 34 31 31 30 36 34 31 5A 30 58 31 0B 30 09
 06 03 55 04 06 13 02 41 55 31 13 30 11 06 03 55
 04 08 0C 0A 53 6F 6D 65 2D 53 74 61 74 65 31 21
 30 1F 06 03 55 04 0A 0C 18 49 6E 74 65 72 6E 65
 74 20 57 69 64 67 69 74 73 20 50 74 79 20 4C 74
 64 31 11 30 0F 06 03 55 04 03 0C 08 64 65 76 69
 63 65 63 61 30 59 30 13 06 07 2A 86 48 CE 3D 02
 01 06 08 2A 86 48 CE 3D 03 01 07 03 42 00 04 12
 8D 17 6D A1 A6 D0 61 29 BB 1C 7A F0 A3 3F A1 53
 73 7E 4E 45 32 85 82 AC E9 8B F6 1F B3 94 BF 9F
 F5 0B 33 A1 AC 89 CA 29 8A 0C 88 8A 7F 02 DE 56
 7B C5 5B 89 99 58 DC 2F BC 5E 8B EA 72 E1 BC 30
 0A 06 08 2A 86 48 CE 3D 04 03 02 03 48 00 30 45
 02 21 00 D5 77 6F 52 9C C1 51 F1 91 85 06 8D E7
 A4 99 6E 4A EE B3 83 E0 3F 85 78 F4 B6 A5 12 CB
 22 70 B8 02 20 4E DD 43 57 03 BD F5 21 4F 73 9D
 09 97 26 CC C7 94 27 0A 84 BC 03 03 51 99 D1 4D
 1E D0 C3 A6 AB
Writing to Oid : E0E1

I followed the original issue of ESP32 Integration. But the code was already as per solution given here in the issue. I un-commented this line It prints 1000 multiple times.

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x1830
load:0x4004c000,len:0x9e8
load:0x40050000,len:0x2b70
entry 0x4004c1ec
I (21) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (21) boot: compile time 12:10:18
I (21) boot: chip revision: 0
I (25) boot.esp32s2: SPI Speed      : 80MHz
I (29) boot.esp32s2: SPI Mode       : DIO
I (34) boot.esp32s2: SPI Flash Size : 4MB
I (38) boot: Enabling RNG early entropy source...
I (44) boot: Partition Table:
I (47) boot: ## Label            Usage          Type ST Offset   Length
I (55) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (62) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (70) boot:  2 factory          factory app      00 00 00010000 00100000
I (77) boot: End of partition table
I (81) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=08da0h ( 36256) map
I (98) esp_image: segment 1: paddr=00018dc8 vaddr=3ffbe430 size=02cd4h ( 11476) load
I (101) esp_image: segment 2: paddr=0001baa4 vaddr=40022000 size=04574h ( 17780) load
I (111) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=1b960h (112992) map
I (139) esp_image: segment 4: paddr=0003b988 vaddr=40026574 size=07eb4h ( 32436) load
I (148) esp_image: segment 5: paddr=00043844 vaddr=50000000 size=00010h (    16) load
I (155) boot: Loaded app from partition at offset 0x10000
I (155) boot: Disabling RNG early entropy source...
I (170) ca��fÆ~
               ��3?����Սѥ��������J���镁�Z%�     ��U��.KH�X,ZY��ine size 32Byte
I (170) cpu_start: Pro cpu up.
I (182) cpu_start: Pro cpu start user code
I (182) cpu_start: cpu freq: 160000000
I (182) cpu_start: Application information:
I (187) cpu_start: Project name:     provision_test_certificate
I (193) cpu_start: App version:      202005.00-3-g722bb54-dirty
I (200) cpu_start: Compile time:     Jul  2 2021 12:10:13
I (206) cpu_start: ELF file SHA256:  787b33a5a1031d62...
I (212) cpu_start: ESP-IDF:          v4.3-dirty
I (217) heap_init: Initializing. RAM available for dynamic allocation:
I (224) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (230) heap_init: At 3FFC20D8 len 00039F28 (231 KiB): DRAM
I (237) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (243) spi_flash: detected chip: generic
I (248) spi_flash: flash io: dio
I (252) cpu_start: Starting scheduler on PRO CPU.
vTaskCallbackHandler
I (457) pal_os_event: Init : Create Timer
I (457) pal_os_event: Init : Create Timer successful
I (457) pal_os_event: oneShot : 1000
I (467) pal_os_event: oneShot : 1000
I (487) pal_os_event: oneShot : 2000
I (507) pal_os_event: oneShot : 12000
I (527) pal_i2c: Initialize pal_i2c_init  
I (527) pal_i2c: init successful
I (537) pal_os_event: oneShot : 1000
I (557) pal_os_event: oneShot : 1000
I (577) pal_os_event: oneShot : 1000
I (597) pal_os_event: oneShot : 1000
I (617) pal_os_event: oneShot : 1000
I (637) pal_os_event: oneShot : 1000
I (657) pal_os_event: oneShot : 1000
I (677) pal_os_event: oneShot : 1000
I (697) pal_os_event: oneShot : 1000
I (717) pal_os_event: oneShot : 1000
I (737) pal_os_event: oneShot : 1000
I (757) pal_os_event: oneShot : 1000
I (777) pal_os_event: oneShot : 1000
I (797) pal_os_event: oneShot : 1000
I (817) pal_os_event: oneShot : 1000
I (837) pal_os_event: oneShot : 1000
I (857) pal_os_event: oneShot : 1000
I (877) pal_os_event: oneShot : 1000
I (897) pal_os_event: oneShot : 1000
I (917) pal_os_event: oneShot : 1000
I (937) pal_os_event: oneShot : 1000
I (957) pal_os_event: oneShot : 1000
I (977) pal_os_event: oneShot : 1000
I (997) pal_os_event: oneShot : 1000
I (1017) pal_os_event: oneShot : 1000
I (1037) pal_os_event: oneShot : 1000
I (1057) pal_os_event: oneShot : 1000
I (1077) pal_os_event: oneShot : 1000
I (1097) pal_os_event: oneShot : 1000
I (1117) pal_os_event: oneShot : 1000
I (1137) pal_os_event: oneShot : 1000
I (1157) pal_os_event: oneShot : 1000
I (1177) pal_os_event: oneShot : 1000
I (1197) pal_os_event: oneShot : 1000
I (1217) pal_os_event: oneShot : 1000
I (1237) pal_os_event: oneShot : 1000
I (1257) pal_os_event: oneShot : 1000
I (1277) pal_os_event: oneShot : 1000
I (1297) pal_os_event: oneShot : 1000
I (1317) pal_os_event: oneShot : 1000
I (1337) pal_os_event: oneShot : 1000
I (1357) pal_os_event: oneShot : 1000
I (1377) pal_os_event: oneShot : 1000
I (1397) pal_os_event: oneShot : 1000
I (1417) pal_os_event: oneShot : 1000
I (1437) pal_os_event: oneShot : 1000
I (1457) pal_os_event: oneShot : 1000
I (1477) pal_os_event: oneShot : 1000
I (1497) pal_os_event: oneShot : 1000
I (1517) pal_os_event: oneShot : 1000
I (1537) pal_os_event: oneShot : 1000
I (1557) pal_os_event: oneShot : 1000
I (1577) pal_os_event: oneShot : 1000
I (1597) pal_os_event: oneShot : 1000
I (1617) pal_os_event: oneShot : 1000
I (1637) pal_os_event: oneShot : 1000
I (1657) pal_os_event: oneShot : 1000
I (1677) pal_os_event: oneShot : 1000
I (1697) pal_os_event: oneShot : 1000
I (1717) pal_os_event: oneShot : 1000
I (1737) pal_os_event: oneShot : 1000
I (1757) pal_os_event: oneShot : 1000
I (1777) pal_os_event: oneShot : 1000
I (1797) pal_os_event: oneShot : 1000
I (1817) pal_os_event: oneShot : 1000
I (1837) pal_os_event: oneShot : 1000
I (1857) pal_os_event: oneShot : 1000
I (1877) pal_os_event: oneShot : 1000
I (1897) pal_os_event: oneShot : 1000
I (1917) pal_os_event: oneShot : 1000
I (1937) pal_os_event: oneShot : 1000
I (1957) pal_os_event: oneShot : 1000
I (1977) pal_os_event: oneShot : 1000
I (1997) pal_os_event: oneShot : 1000
I (2017) pal_os_event: oneShot : 1000
I (2037) pal_os_event: oneShot : 1000
I (2057) pal_os_event: oneShot : 1000
I (2077) pal_os_event: oneShot : 1000
I (2097) pal_os_event: oneShot : 1000
I (2117) pal_os_event: oneShot : 1000
I (2137) pal_os_event: oneShot : 1000
I (2157) pal_os_event: oneShot : 1000
I (2177) pal_os_event: oneShot : 1000
I (2197) pal_os_event: oneShot : 1000
I (2217) pal_os_event: oneShot : 1000
I (2237) pal_os_event: oneShot : 1000
I (2257) pal_os_event: oneShot : 1000
I (2277) pal_os_event: oneShot : 1000
I (2297) pal_os_event: oneShot : 1000
I (2317) pal_os_event: oneShot : 1000
I (2337) pal_os_event: oneShot : 1000
I (2357) pal_os_event: oneShot : 1000
I (2377) pal_os_event: oneShot : 1000
I (2397) pal_os_event: oneShot : 1000
I (2417) pal_os_event: oneShot : 1000
I (2437) pal_os_event: oneShot : 1000
I (2457) pal_os_event: oneShot : 1000
I (2477) pal_os_event: oneShot : 1000
I (2497) pal_os_event: oneShot : 1000
I (2517) pal_os_event: oneShot : 1000
I (2537) pal_os_event: oneShot : 1000
I (2557) pal_os_event: oneShot : 1000
I (2577) pal_os_event: oneShot : 1000
I (2597) pal_os_event: oneShot : 1000
I (2617) pal_os_event: oneShot : 1000
I (2637) pal_os_event: oneShot : 1000
I (2657) pal_os_event: oneShot : 1000
I (2677) pal_os_event: oneShot : 1000
I (2697) pal_os_event: oneShot : 1000
I (2717) pal_os_event: oneShot : 1000
I (2737) pal_os_event: oneShot : 1000
I (2757) pal_os_event: oneShot : 1000
I (2777) pal_os_event: oneShot : 1000
I (2797) pal_os_event: oneShot : 1000
I (2817) pal_os_event: oneShot : 1000
I (2837) pal_os_event: oneShot : 1000
I (2857) pal_os_event: oneShot : 1000
I (2877) pal_os_event: oneShot : 1000
I (2897) pal_os_event: oneShot : 1000
I (2917) pal_os_event: oneShot : 1000
I (2937) pal_os_event: oneShot : 1000
I (2957) pal_os_event: oneShot : 1000
I (2977) pal_os_event: oneShot : 1000
I (2997) pal_os_event: oneShot : 1000
I (3017) pal_os_event: oneShot : 1000
I (3037) pal_os_event: oneShot : 1000
I (3057) pal_os_event: oneShot : 1000
I (3077) pal_os_event: oneShot : 1000
I (3097) pal_os_event: oneShot : 1000
I (3117) pal_os_event: oneShot : 1000
I (3137) pal_os_event: oneShot : 1000
I (3157) pal_os_event: oneShot : 1000
I (3177) pal_os_event: oneShot : 1000
I (3197) pal_os_event: oneShot : 1000
I (3217) pal_os_event: oneShot : 1000
I (3237) pal_os_event: oneShot : 1000
I (3257) pal_os_event: oneShot : 1000
I (3277) pal_os_event: oneShot : 1000
I (3297) pal_os_event: oneShot : 1000
I (3317) pal_os_event: oneShot : 1000
I (3337) pal_os_event: oneShot : 1000
I (3357) pal_os_event: oneShot : 1000
I (3377) pal_os_event: oneShot : 1000
I (3397) pal_os_event: oneShot : 1000
I (3417) pal_os_event: oneShot : 1000
I (3437) pal_os_event: oneShot : 1000
I (3457) pal_os_event: oneShot : 1000
I (3477) pal_os_event: oneShot : 1000
I (3497) pal_os_event: oneShot : 1000
I (3517) pal_os_event: oneShot : 1000
I (3537) pal_os_event: oneShot : 1000
I (3557) pal_os_event: oneShot : 1000
I (3577) pal_os_event: oneShot : 1000
I (3597) pal_os_event: oneShot : 1000
I (3617) pal_os_event: oneShot : 1000
I (3637) pal_os_event: oneShot : 1000
I (3657) pal_os_event: oneShot : 1000
I (3677) pal_os_event: oneShot : 1000
I (3697) pal_os_event: oneShot : 1000
I (3717) pal_os_event: oneShot : 1000
I (3737) pal_os_event: oneShot : 1000
I (3757) pal_os_event: oneShot : 1000
I (3777) pal_os_event: oneShot : 1000
I (3797) pal_os_event: oneShot : 1000
I (3817) pal_os_event: oneShot : 1000
I (3837) pal_os_event: oneShot : 1000
I (3857) pal_os_event: oneShot : 1000
I (3877) pal_os_event: oneShot : 1000
I (3897) pal_os_event: oneShot : 1000
I (3917) pal_os_event: oneShot : 1000
I (3937) pal_os_event: oneShot : 1000
I (3957) pal_os_event: oneShot : 1000
I (3977) pal_os_event: oneShot : 1000
I (3997) pal_os_event: oneShot : 1000
I (4017) pal_os_event: oneShot : 1000
I (4037) pal_os_event: oneShot : 1000
I (4057) pal_os_event: oneShot : 1000
I (4077) pal_os_event: oneShot : 1000
I (4097) pal_os_event: oneShot : 1000
I (4117) pal_os_event: oneShot : 1000
I (4137) pal_os_event: oneShot : 1000
I (4157) pal_os_event: oneShot : 1000
I (4177) pal_os_event: oneShot : 1000
I (4197) pal_os_event: oneShot : 1000
I (4217) pal_os_event: oneShot : 1000
I (4237) pal_os_event: oneShot : 1000
I (4257) pal_os_event: oneShot : 1000
I (4277) pal_os_event: oneShot : 1000
I (4297) pal_os_event: oneShot : 1000
I (4317) pal_os_event: oneShot : 1000
I (4337) pal_os_event: oneShot : 1000
I (4357) pal_os_event: oneShot : 1000
I (4377) pal_os_event: oneShot : 1000
I (4397) pal_os_event: oneShot : 1000
I (4417) pal_os_event: oneShot : 1000
I (4437) pal_os_event: oneShot : 1000
I (4457) pal_os_event: oneShot : 1000
I (4477) pal_os_event: oneShot : 1000
I (4497) pal_os_event: oneShot : 1000
I (4517) pal_os_event: oneShot : 1000
I
 30 82 01 A1 30 82 01 47 02 09 00 DA 1B 1B EA 7D
 2F 17 56 30 0A 06 08 2A 86 48 CE 3D 04 03 02 30
 59 31 0B 30 09 06 03 55 04 06 13 02 49 4E 31 0C
 30 0A 06 03 55 04 08 0C 03 4B 41 52 31 0D 30 0B
 06 03 55 04 07 0C 04 42 41 4E 47 31 0D 30 0B 06
I (4547) pal_os_event: oneShot : 1000
 03 55 04 0A 0C 04 49 46 49 4E 31 0C 30 0A 06 03
 55 04 0B 0C 03 44 53 53 31 10 30 0E 06 03 55 04
 03 0C 07 41 7A 75 72 65 43 41 30 1E 17 0D 32 30
I (4567) pal_os_event: oneShot : 1000
 30 37 31 32 31 31 30 36 34 31 5A 17 0D 32 31 31
 31 32 34 31 31 30 36 34 31 5A 30 58 31 0B 30 09
 06 03 55 04 06 13 02 41 55 31 13 30 11 06 03 55
 04 08 0C 0A 53 6F 6D 65 2D 53 74 61 74 65 31 21
I (4587) pal_os_event: oneShot : 1000
 30 1F 06 03 55 04 0A 0C 18 49 6E 74 65 72 6E 65
 74 20 57 69 64 67 69 74 73 20 50 74 79 20 4C 74
 64 31 11 30 0F 06 03 55 04 03 0C 08 64 65 76 69
 63 65 63 61 30 59 30 13 06 07 2A 86 48 CE 3D 02
I (4607) pal_os_event: oneShot : 1000
 01 06 08 2A 86 48 CE 3D 03 01 07 03 42 00 04 12
 8D 17 6D A1 A6 D0 61 29 BB 1C 7A F0 A3 3F A1 53
 73 7E 4E 45 32 85 82 AC E9 8B F6 1F B3 94 BF 9F
I (4627) pal_os_event: oneShot : 1000
 F5 0B 33 A1 AC 89 CA 29 8A 0C 88 8A 7F 02 DE 56
 7B C5 5B 89 99 58 DC 2F BC 5E 8B EA 72 E1 BC 30
 0A 06 08 2A 86 48 CE 3D 04 03 02 03 48 00 30 45
 02 21 00 D5 77 6F 52 9C C1 51 F1 91 85 06 8D E7
I (4647) pal_os_event: oneShot : 1000
 A4 99 6E 4A EE B3 83 E0 3F 85 78 F4 B6 A5 12 CB
 22 70 B8 02 20 4E DD 43 57 03 BD F5 21 4F 73 9D
 09 97 26 CC C7 94 27 0A 84 BC 03 03 51 99 D1 4D
I (4667) pal_os_event: oneShot : 1000
 1E D0 C3 A6 AB
Writing to Oid : E0E1
I (4687) pal_os_event: oneShot : 1000
I (4707) pal_os_event: oneShot : 1000
I (4717) pal_os_event: oneShot : 1000
I (4727) pal_os_event: oneShot : 1000
I (4737) pal_os_event: oneShot : 1000
I (4747) pal_os_event: oneShot : 1000
I (4757) pal_os_event: oneShot : 1000
I (4767) pal_os_event: oneShot : 1000
I (4777) pal_os_event: oneShot : 1000
I (4787) pal_os_event: oneShot : 1000
I (4797) pal_os_event: oneShot : 1000
I (4807) pal_os_event: oneShot : 1000
I (4817) pal_os_event: oneShot : 1000

And then it continues same.

markandpathak commented 3 years ago

I also tried to uncomment this line.

https://github.com/Infineon/optiga-trust-m/blob/d57dd0a8a858c11c7754c6aac83b8e560756db60/pal/esp32_freertos/pal_i2c.c#L151

After this I received a stream of w-failure in the output. Can it be some issue?

ayushev commented 3 years ago

it looks like you have it working already, please revert back you changes done recently ("with oneShot: 1000"). What will happen if you remove this certificaite and put "" instead there. You should be able to see a new keypair to be generated.

markandpathak commented 3 years ago

As per your suggestion I tried that. Here is the output.

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x1830
load:0x4004c000,len:0x9e8
load:0x40050000,len:0x2b70
entry 0x4004c1ec
I (21) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (21) boot: compile time 12:10:18
I (21) boot: chip revision: 0
I (25) boot.esp32s2: SPI Speed      : 80MHz
I (29) boot.esp32s2: SPI Mode       : DIO
I (34) boot.esp32s2: SPI Flash Size : 4MB
I (38) boot: Enabling RNG early entropy source...
I (44) boot: Partition Table:
I (47) boot: ## Label            Usage          Type ST Offset   Length
I (55) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (62) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (70) boot:  2 factory          factory app      00 00 00010000 00100000
I (77) boot: End of partition table
I (81) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=08e90h ( 36496) map
I (98) esp_image: segment 1: paddr=00018eb8 vaddr=3ffbe590 size=02cd4h ( 11476) load
I (101) esp_image: segment 2: paddr=0001bb94 vaddr=40022000 size=04484h ( 17540) load
I (111) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=1ef84h (126852) map
I (142) esp_image: segment 4: paddr=0003efac vaddr=40026484 size=08108h ( 33032) load
I (151) esp_image: segment 5: paddr=000470bc vaddr=50000000 size=00010h (    16) load
I (158) boot: Loaded app from partition at offset 0x10000
I (159) boot: Disabling RNG early entropy source...
I (173) cac��f<��3?����,W��
                           �V�,ZY�B��size 8KB, 4Ways, cache line size 32Byte
I (173) cpu_start: Pro cpu up.
I (185) cpu_start: Pro cpu start user code
I (185) cpu_start: cpu freq: 160000000
I (185) cpu_start: Application information:
I (190) cpu_start: Project name:     provision_test_certificate
I (196) cpu_start: App version:      202005.00-3-g722bb54-dirty
I (203) cpu_start: Compile time:     Jul  2 2021 14:11:58
I (209) cpu_start: ELF file SHA256:  cf023454a7bea382...
I (215) cpu_start: ESP-IDF:          v4.3-dirty
I (220) heap_init: Initializing. RAM available for dynamic allocation:
I (227) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (233) heap_init: At 3FFC2238 len 00039DC8 (231 KiB): DRAM
I (240) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (246) spi_flash: detected chip: generic
I (251) spi_flash: flash io: dio
I (255) cpu_start: Starting scheduler on PRO CPU.
vTaskCallbackHandler
I (460) pal_os_event: Init : Create Timer
I (460) pal_os_event: Init : Create Timer successful
I (530) pal_i2c: Initialize pal_i2c_init  
I (530) pal_i2c: I2C SDA:33 SCL34 Bitrate:400000
I (530) pal_i2c: init successful

Write certficate failed
ayushev commented 3 years ago

Sorry, my bad, the value should be 0 #define CERTIFICATE (0)

markandpathak commented 3 years ago

That's also failing. I selected NIST P-256 curve certificate generation. 

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x1830
load:0x4004c000,len:0x9e8
load:0x40050000,len:0x2b70
entry 0x4004c1ec
I (21) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (21) boot: compile time 12:10:18
I (21) boot: chip revision: 0
I (24) boot.esp32s2: SPI Speed      : 80MHz
I (29) boot.esp32s2: SPI Mode       : DIO
I (34) boot.esp32s2: SPI Flash Size : 4MB
I (38) boot: Enabling RNG early entropy source...
I (44) boot: Partition Table:
I (47) boot: ## Label            Usage          Type ST Offset   Length
I (55) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (62) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (70) boot:  2 factory          factory app      00 00 00010000 00100000
I (77) boot: End of partition table
I (81) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=08ff8h ( 36856) map
I (98) esp_image: segment 1: paddr=00019020 vaddr=3ffbe590 size=02cd4h ( 11476) load
I (101) esp_image: segment 2: paddr=0001bcfc vaddr=40022000 size=0431ch ( 17180) load
I (111) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=1f4ech (128236) map
I (143) esp_image: segment 4: paddr=0003f514 vaddr=4002631c size=08270h ( 33392) load
I (152) esp_image: segment 5: paddr=0004778c vaddr=50000000 size=00010h (    16) load
I (159) boot: Loaded app from partition at offset 0x10000
I (159) boot: Disabling RNG early entropy source...
I (173) ca��fÆ~
               ��3?����Սѥ��������J���镁�Z%�     ��U��.KH�X,ZY��ine size 32Byte
I (173) cpu_start: Pro cpu up.
I (185) cpu_start: Pro cpu start user code
I (185) cpu_start: cpu freq: 160000000
I (185) cpu_start: Application information:
I (190) cpu_start: Project name:     provision_test_certificate
I (196) cpu_start: App version:      202005.00-3-g722bb54-dirty
I (203) cpu_start: Compile time:     Jul  2 2021 14:11:58
I (209) cpu_start: ELF file SHA256:  2172401969874eeb...
I (215) cpu_start: ESP-IDF:          v4.3-dirty
I (220) heap_init: Initializing. RAM available for dynamic allocation:
I (228) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (234) heap_init: At 3FFC2238 len 00039DC8 (231 KiB): DRAM
I (240) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (247) spi_flash: detected chip: generic
I (251) spi_flash: flash io: dio
I (255) cpu_start: Starting scheduler on PRO CPU.
vTaskCallbackHandler
I (460) pal_os_event: Init : Create Timer
I (460) pal_os_event: Init : Create Timer successful
I (530) pal_i2c: Initialize pal_i2c_init  
I (530) pal_i2c: I2C SDA:33 SCL34 Bitrate:400000
I (530) pal_i2c: init successful

Select the key type from below list
Press 1 to Generate NIST P-256
Press 2 to Generate NIST P-384
Press 3 to Generate RSA 1024
Press 4 to Generate RSA 2048

Selected NIST P-256 Curve
Generating keypair in Oid E0F1
202
Key Pair generation failed
ayushev commented 3 years ago

To try things out could you üease try two things: 1) Change the reset tyep to the software reset - https://github.com/Infineon/optiga-trust-m/blob/trust_m1_m3/optiga/include/optiga/optiga_lib_config_m_v3.h#L114 it should be 1 instead of 0 2) If the above doesn't change anything, could you please enable logs by uncommenting the following lines - https://github.com/Infineon/optiga-trust-m/blob/trust_m1_m3/optiga/include/optiga/optiga_lib_config_m_v3.h#L136-L143

markandpathak commented 3 years ago

Here is the output with reset type changed and log enabled. There wasn't any blob directory in azure package but there was a optiga_lib_config.h in include folder. During first test, I observed that RST was low all the time. Hence using GPIO I kept it HIGH all the time but output remained same.

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x1830
load:0x4004c000,len:0x9e8
load:0x40050000,len:0x2b70
entry 0x4004c1ec
I (21) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (21) boot: compile time 12:10:18
I (21) boot: chip revision: 0
I (24) boot.esp32s2: SPI Speed      : 80MHz
I (29) boot.esp32s2: SPI Mode       : DIO
I (34) boot.esp32s2: SPI Flash Size : 4MB
I (38) boot: Enabling RNG early entropy source...
I (44) boot: Partition Table:
I (47) boot: ## Label            Usage          Type ST Offset   Length
I (55) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (62) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (70) boot:  2 factory          factory app      00 00 00010000 00100000
I (77) boot: End of partition table
I (81) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=09550h ( 38224) map
I (98) esp_image: segment 1: paddr=00019578 vaddr=3ffbe590 size=02cdch ( 11484) load
I (101) esp_image: segment 2: paddr=0001c25c vaddr=40022000 size=03dbch ( 15804) load
I (111) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=1fa2ch (129580) map
I (143) esp_image: segment 4: paddr=0003fa54 vaddr=40025dbc size=087d0h ( 34768) load
I (152) esp_image: segment 5: paddr=0004822c vaddr=50000000 size=00010h (    16) load
I (159) boot: Loaded app from partition at offset 0x10000
I (160) boot: Disabling RNG early entropy source...
I (174) cac��f<��3?����,W��
                           �V�,ZY�B��size 8KB, 4Ways, cache line size 32Byte
I (174) cpu_start: Pro cpu up.
I (185) cpu_start: Pro cpu start user code
I (186) cpu_start: cpu freq: 160000000
I (186) cpu_start: Application information:
I (190) cpu_start: Project name:     provision_test_certificate
I (197) cpu_start: App version:      202005.00-3-g722bb54-dirty
I (203) cpu_start: Compile time:     Jul  2 2021 14:11:58
I (209) cpu_start: ELF file SHA256:  1849f23d546e667c...
I (215) cpu_start: ESP-IDF:          v4.3-dirty
I (221) heap_init: Initializing. RAM available for dynamic allocation:
I (228) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (234) heap_init: At 3FFC2240 len 00039DC0 (231 KiB): DRAM
I (240) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (247) spi_flash: detected chip: generic
I (251) spi_flash: flash io: dio
I (256) cpu_start: Starting scheduler on PRO CPU.
vTaskCallbackHandler
I (461) pal_os_event: Init : Create Timer
I (461) pal_os_event: Init : Create Timer successful
[optiga util]     : OPTIGA Trust initializationI (461) : 

I (461) : 

[optiga util]     : optiga_util_open_applicationI (471) : 

I (471) : 

[optiga cmd]      : optiga_cmd_open_applicationI (481) : 

I (481) : 

I (521) pal_i2c: Initialize pal_i2c_init  
I (521) pal_i2c: I2C SDA:33 SCL34 Bitrate:400000
I (521) pal_i2c: init successful
[optig
Select the key type from below list
Press 1 to Generate NIST P-256
Press 2 to Generate NIST P-384
Press 3 to Generate RSA 1024
Press 4 to Generate RSA 2048

Selected NIST P-256 Curve
Generating keypair in Oid E0F1
[optiga crypt]    : optiga_crypt_ecc_generate_keypairI (11041) : 

I (11041) : 

[optiga cmd]      : optiga_cmd_gen_keypairI (11041) : 

I (11051) : 

[optiga cmd]      : Sending generate keypair command..I (11071) : 

I (11071) : 

[optiga crypt]    : Call back status errorI (11081) : 

I (11081) : 

202
Key Pair generation failed
markandpathak commented 3 years ago

I tried on multiple hardware prototypes, just to eliminate possibility of defective IC, but all result remained same. Circuit wise it's very simple. 3.3V connected to Vcc. SCL and SDA goes to ESP32 directly with 10k pull up on both. RST is connected to a GPIO on ESP32. So I don't think that this can be an hardware issue. There no other I2C devices on bus. There is a log Optiga Trust Initialization. Does that mean the ESP can reach the IC?

markandpathak commented 3 years ago

Just checking out possibilities. Is it possible that the azure example is not compatible with Optiga Trust M V3? My hardware uses V3. As there is no file which you mentioned here in the repo I cloned. I think it is V3 specific config.: https://github.com/Infineon/optiga-trust-m/blob/trust_m1_m3/optiga/include/optiga/optiga_lib_config_m_v3.h#L136-L143. Azure repo just has optiga_lib_config.h.

ayushev commented 3 years ago

I've udpate the code and tested it on the 4.3 (it was originally build for the 4.1). It should work, youcl you please update your repository. Also please check again whetehr you have all teh pins selected correctly, and ECC Private key (second private key) is selected by default.

markandpathak commented 3 years ago

Hello @ayushev, I tried with new repo but same result. Here is the output.

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x1830
load:0x4004c000,len:0x9e8
load:0x40050000,len:0x2b70
entry 0x4004c1ec
I (21) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (21) boot: compile time 11:31:53
I (21) boot: chip revision: 0
I (24) boot.esp32s2: SPI Speed      : 80MHz
I (29) boot.esp32s2: SPI Mode       : DIO
I (34) boot.esp32s2: SPI Flash Size : 4MB
I (38) boot: Enabling RNG early entropy source...
I (44) boot: Partition Table:
I (47) boot: ## Label            Usage          Type ST Offset   Length
I (55) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (62) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (70) boot:  2 factory          factory app      00 00 00010000 00100000
I (77) boot: End of partition table
I (81) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=09e80h ( 40576) map
I (98) esp_image: segment 1: paddr=00019ea8 vaddr=3ffbe590 size=02ce4h ( 11492) load
I (101) esp_image: segment 2: paddr=0001cb94 vaddr=40022000 size=03484h ( 13444) load
I (110) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=203c0h (132032) map
I (143) esp_image: segment 4: paddr=000403e8 vaddr=40025484 size=09108h ( 37128) load
I (153) esp_image: segment 5: paddr=000494f8 vaddr=50000000 size=00010h (    16) load
I (161) boot: Loaded app from partition at offset 0x10000
I (161) boot: Disabling RNG early entropy source...
I (174) ca��fÆ~
               ��3?��]�],]Z�
                            �V�,ZY�B��size 8KB, 4Ways, cache line size 32Byte
I (174) cpu_start: Pro cpu up.
I (186) cpu_start: Pro cpu start user code
I (186) cpu_start: cpu freq: 160000000
I (186) cpu_start: Application information:
I (191) cpu_start: Project name:     provision_test_certificate
I (197) cpu_start: App version:      202005.00-6-gd0d8690-dirty
I (204) cpu_start: Compile time:     Jul  6 2021 11:46:29
I (210) cpu_start: ELF file SHA256:  4027ebe53cbea321...
I (216) cpu_start: ESP-IDF:          v4.3-dirty
I (221) heap_init: Initializing. RAM available for dynamic allocation:
I (228) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (235) heap_init: At 3FFC2248 len 00039DB8 (231 KiB): DRAM
I (241) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (247) spi_flash: detected chip: generic
I (252) spi_flash: flash io: dio
I (256) cpu_start: Starting scheduler on PRO CPU.
I (261) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (361) pal_os_event: Init : Create Timer
I (361) pal_os_event: Init : Create Timer successful
[optiga util]     : OPTIGA Trust initialization
[optiga util]     : optiga_util_open_application
[optiga cmd]      : optiga_cmd_open_application
I (451) pal_i2c: Initialize pal_i2c_init  
I (451) pal_i2c: init successful
[opt
Select the key type from below list
Press 1 to Generate NIST P-256
Press 2 to Generate NIST P-384
Press 3 to Generate NIST P-521
Press 4 to Generate Brainpool 256 r1
Press 5 to Generate Brainpool 384 r1
Press 6 to Generate Brainpool 512 r1
Press 7 to Generate RSA 1024
Press 8 to Generate RSA 2048

Selected NIST P-256 Curve
Generating keypair in Oid E0F0
[optiga crypt]    : optiga_crypt_ecc_generate_keypair
[optiga cmd]      : optiga_cmd_gen_keypair
[optiga cmd]      : Sending generate keypair command..
[optiga crypt]    : Call back status error
202
Key Pair generation failed
ayushev commented 3 years ago

Hi @markandpathak you need to select a correct ECC Private key, you should take on of unlocked, for instance second, third or fourth ECC Private Key + a corresponding certificate slot. Could you please additionally enable logging similar to what I explained above.

markandpathak commented 3 years ago

Hello @ayushev , As per your suggestions, I selected 2nd Key slot and 2nd Certificate slot in config. Double checked the pins and turned on logs by uncommenting 4 log definitions in optiga_lib_config_m_v3.h. Here is the output. 

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x1830
load:0x4004c000,len:0x9e8
load:0x40050000,len:0x2b70
SHA-256 comparison failed:
Calculated: 89dd7a5e205d897961c59f847ded89b3829cd434f6d4cfb09e8f6eea74d3efd1
Expected: 68993744f5b84880edf0d1e26d76552739a4dbfab466afa1b0188c36999fb90b
Attempting to boot anyway...
entry 0x4004c1ec
I (40) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (40) boot: compile time 13:38:50
I (40) boot: chip revision: 0
I (43) boot.esp32s2: SPI Speed      : 80MHz
I (47) boot.esp32s2: SPI Mode       : DIO
I (52) boot.esp32s2: SPI Flash Size : 4MB
I (57) boot: Enabling RNG early entropy source...
I (62) boot: Partition Table:
I (66) boot: ## Label            Usage          Type ST Offset   Length
I (73) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (81) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (88) boot:  2 factory          factory app      00 00 00010000 00100000
I (95) boot: End of partition table
I (100) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=096d8h ( 38616) map
I (117) esp_image: segment 1: paddr=00019700 vaddr=3ffbe590 size=02ce4h ( 11492) load
I (120) esp_image: segment 2: paddr=0001c3ec vaddr=40022000 size=03c2ch ( 15404) load
I (129) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=1fd50h (130384) map
I (162) esp_image: segment 4: paddr=0003fd78 vaddr=40025c2c size=08960h ( 35168) load
I (171) esp_image: segment 5: paddr=000486e0 vaddr=50000000 size=00010h (    16) load
I (178) boot: Loaded app from partition at offset 0x10000
I (178) boot: Disabling RNG early entropy source...
I (192) cac��f<��3?����f��`tion cache   : size 8KB, 4Ways, cache line size 32Byte
I (193) cpu_start: Pro cpu up.
I (204) cpu_start: Pro cpu start user code
I (204) cpu_start: cpu freq: 160000000
I (204) cpu_start: Application information:
I (209) cpu_start: Project name:     provision_test_certificate
I (215) cpu_start: App version:      202005.00-6-gd0d8690-dirty
I (222) cpu_start: Compile time:     Jul  6 2021 13:38:44
I (228) cpu_start: ELF file SHA256:  41c199aa8de225ce...
I (234) cpu_start: ESP-IDF:          v4.3-dirty
I (239) heap_init: Initializing. RAM available for dynamic allocation:
I (247) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (253) heap_init: At 3FFC2248 len 00039DB8 (231 KiB): DRAM
I (259) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (266) spi_flash: detected chip: generic
I (270) spi_flash: flash io: dio
I (274) cpu_start: Starting scheduler on PRO CPU.
I (479) pal_os_event: Init : Create Timer
I (479) pal_os_event: Init : Create Timer successful
[optiga util]     : OPTIGA Trust initialization
[optiga util]     : optiga_util_open_application
[optiga cmd]      : optiga_cmd_open_application
I (569) pal_i2c: Initialize pal_i2c_init  
I (569) pal_i2c: init successful
[opt
Select the key type from below list
Press 1 to Generate NIST P-256
Press 2 to Generate NIST P-384
Press 3 to Generate NIST P-521
Press 4 to Generate Brainpool 256 r1
Press 5 to Generate Brainpool 384 r1
Press 6 to Generate Brainpool 512 r1
Press 7 to Generate RSA 1024
Press 8 to Generate RSA 2048

Selected NIST P-256 Curve
Generating keypair in Oid E0F1
[optiga crypt]    : optiga_crypt_ecc_generate_keypair
[optiga cmd]      : optiga_cmd_gen_keypair
[optiga cmd]      : Sending generate keypair command..
[optiga crypt]    : Call back status error
202
Key Pair generation failed
markandpathak commented 3 years ago

I've checked in pal_i2c write by uncommenting the ESP_LOG lines. i2c_write always returns w failure. And if err code if checked it is always ESP_FAIL which is a generic error code.

ayushev commented 3 years ago

Can you try to put here the log which you have enabled for the i2c write and read. Here is my output fro your reference, I've cloned the fresh code and compiled it

Long logging ``` rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0030,len:7040 load:0x40078000,len:14292 ho 0 tail 12 room 4 load:0x40080400,len:3688 0x40080400: _init at ??:? entry 0x40080678 I (28) boot: ESP-IDF v4.3-beta3-195-g6be10fab0 2nd stage bootloader I (28) boot: compile time 12:14:39 I (28) boot: chip revision: 1 I (33) boot_comm: chip revision: 1, min. bootloader chip revision: 0 I (40) boot.esp32: SPI Speed : 40MHz I (45) boot.esp32: SPI Mode : DIO I (49) boot.esp32: SPI Flash Size : 4MB I (54) boot: Enabling RNG early entropy source... I (59) boot: Partition Table: I (63) boot: ## Label Usage Type ST Offset Length I (70) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (77) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (85) boot: 2 factory factory app 00 00 00010000 00100000 I (92) boot: End of partition table I (96) boot_comm: chip revision: 1, min. application chip revision: 0 I (104) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=0a404h ( 41988) map I (128) esp_image: segment 1: paddr=0001a42c vaddr=3ffb0000 size=02ec8h ( 11976) load I (133) esp_image: segment 2: paddr=0001d2fc vaddr=40080000 size=02d1ch ( 11548) load I (139) esp_image: segment 3: paddr=00020020 vaddr=400d0020 size=221ach (139692) map I (195) esp_image: segment 4: paddr=000421d4 vaddr=40082d1c size=09a4ch ( 39500) load I (212) esp_image: segment 5: paddr=0004bc28 vaddr=50000000 size=00010h ( 16) load I (219) boot: Loaded app from partition at offset 0x10000 I (220) boot: Disabling RNG early entropy source... I (232) cpu_start: Pro cpu up. I (232) cpu_start: Starting app cpu, entry point is 0x40081180 0x40081180: call_start_cpu1 at /mnt/c/Users/Yushev/git/esp-idf/components/esp_system/port/cpu_start.c:141 I (0) cpu_start: App cpu up. I (247) cpu_start: Pro cpu start user code I (247) cpu_start: cpu freq: 160000000 I (247) cpu_start: Application information: I (251) cpu_start: Project name: provision_test_certificate I (258) cpu_start: App version: 202005.00-6-gd0d8690 I (264) cpu_start: Compile time: Jul 6 2021 12:24:46 I (270) cpu_start: ELF file SHA256: 99b7b9bc68debc18... I (276) cpu_start: ESP-IDF: v4.3-beta3-195-g6be10fab0 I (283) heap_init: Initializing. RAM available for dynamic allocation: I (290) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM I (296) heap_init: At 3FFB3F30 len 0002C0D0 (176 KiB): DRAM I (302) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (308) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (315) heap_init: At 4008C768 len 00013898 (78 KiB): IRAM I (322) spi_flash: detected chip: generic I (326) spi_flash: flash io: dio I (331) cpu_start: Starting scheduler on PRO CPU. I (0) cpu_start: Starting scheduler on APP CPU. I (535) pal_os_event: Init : Create Timer I (535) pal_os_event: Init : Create Timer successful [optiga util] : OPTIGA Trust initialization [optiga util] : optiga_util_open_application [optiga cmd] : optiga_cmd_open_application I (625) pal_i2c: Initialize pal_i2c_init I (625) pal_i2c: init successful I (625) pal_i2c : W:: 84 I (635) pal_i2c : R:: 00 00 01 90 I (645) pal_i2c: W-Failure I (655) pal_i2c : W:: 81 01 15 I (665) pal_i2c: W-Failure I (675) pal_i2c: W-Failure I (685) pal_i2c : W:: 81 I (695) pal_i2c : R:: 01 15 [optiga cmd] : Sending open app command... [optiga comms] : >>>> Length of data - 0x001B I (725) pal_i2c: W-Failure16 08 20 F0 00 00 10 D2 76 00 00 04 47 65 6E 41 75 74 68 41 70 70 6C BE 40 I (745) pal_i2c: W-Failure I (755) pal_i2c: W-Failure I (765) pal_i2c: W-Failure I (775) pal_i2c: W-Failure I (785) pal_i2c : W:: 80 03 00 16 08 20 f0 00 00 10 d2 76 00 00 04 47 I (785) pal_i2c : W:: 65 6e 41 75 74 68 41 70 70 6c be 40 I (795) pal_i2c : W:: 82 I (805) pal_i2c : R:: 48 80 00 0b I (815) pal_i2c : W:: 80 I (825) pal_i2c : R:: 00 00 06 08 20 00 00 00 00 19 04 [optiga comms] : <<<< Length of data - 0x000B I (835) pal_i2c : W:: 80 80 00 00 0c ec 00 00 19 04 [optiga cmd] : Processing response for open app command... [optiga cmd] : Respo Select the key type from below list Press 1 to Generate NIST P-256 Press 2 to Generate NIST P-384 Press 3 to Generate NIST P-521 Press 4 to Generate Brainpool 256 r1 Press 5 to Generate Brainpool 384 r1 Press 6 to Generate Brainpool 512 r1 Press 7 to Generate RSA 1024 Press 8 to Generate RSA 2048 Selected NIST P-256 Curve Generating keypair in Oid E0F1 [optiga crypt] : optiga_crypt_ecc_generate_keypair [optiga cmd] : optiga_cmd_gen_keypair [optiga cmd] : Sending generate keypair command.. [optiga comms] : >>>> Length of data - 0x0014 I (21085) pal_i2c: W-Failure 08 20 B8 03 00 09 01 00 02 E0 F1 02 00 01 11 66 AE I (21105) pal_i2c: W-Failure I (21115) pal_i2c: W-Failure I (21125) pal_i2c : W:: 80 04 00 0f 08 20 b8 03 00 09 01 00 02 e0 f1 02 I (21125) pal_i2c : W:: 00 01 11 66 ae I (21135) pal_i2c : W:: 82 I (21145) pal_i2c : R:: c8 80 00 05 I (21155) pal_i2c : W:: 80 I (21165) pal_i2c : R:: 81 00 00 56 30 I (21175) pal_i2c : W:: 82 I (21185) pal_i2c : R:: 88 80 00 00 I (21205) pal_i2c : W:: 82 I (21215) pal_i2c : R:: 48 80 00 52 I (21225) pal_i2c : W:: 80 I (21235) pal_i2c : R:: 05 00 4d 08 20 00 00 00 47 02 00 44 03 42 00 04 I (21235) pal_i2c : R:: 0b eb 9f 0d b0 b5 a4 e8 ba 73 b0 33 dc d8 a9 a0 I (21235) pal_i2c : R:: 30 f2 76 8c d2 ca cb 0a a2 dd 83 85 78 42 ab 03 I (21245) pal_i2c : R:: bf e9 68 14 8b fd 8d 85 55 74 38 e2 20 3c 2c 18 I (21255) pal_i2c : R:: 3d 60 46 50 ac 25 b0 da 02 f5 3c d5 35 f9 36 df I (21255) pal_i2c : R:: 78 cb [optiga comms] : <<<< Length of data - 0x0052 I (21295) pal_i2c : W:: 80 81 00 00 56 30 A 02 F5 3C D5 35 F9 36 DF 78 CB 68 14 8B FD 8D 85 55 74 38 E2 20 3C 2C 18 [optiga cmd] : Processing response for generate keypair command... [optiga cmd] : Response of generate keypair command is processed... 30 59 30 13 06 07 2A 86 48 CE 3D 02 01 06 08 2A 86 48 CE 3D 03 01 07 03 42 00 04 0B EB 9F 0D B0 B5 A4 E8 BA 73 B0 33 DC D8 A9 A0 30 F2 76 8C D2 CA CB 0A A2 DD 83 85 78 42 AB 03 BF E9 68 14 8B FD 8D 85 55 74 38 E2 20 3C 2C 18 3D 60 46 50 AC 25 B0 DA 02 F5 3C D5 35 F9 36 DF PEM format public key -----BEGIN PUBLIC KEY----- MFkwEwYHKoZIzj0CAQYIKoZIzj0DAQcDQgAEC+ufDbC1pOi6c7Az3NipoDDydozS yssKot2DhXhCqwO/6WgUi/2NhVV0OOIgPCwYPWBGUKwlsNoC9TzVNfk23w== -----END PUBLIC KEY----- [optiga crypt] : Generate Key Pair successful!!! ```
markandpathak commented 3 years ago

Here is the log.

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x1830
load:0x4004c000,len:0x9e8
load:0x40050000,len:0x2b70
SHA-256 comparison failed:
Calculated: 89dd7a5e205d897961c59f847ded89b3829cd434f6d4cfb09e8f6eea74d3efd1
Expected: 68993744f5b84880edf0d1e26d76552739a4dbfab466afa1b0188c36999fb90b
Attempting to boot anyway...
entry 0x4004c1ec
I (40) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (40) boot: compile time 13:38:50
I (40) boot: chip revision: 0
I (43) boot.esp32s2: SPI Speed      : 80MHz
I (47) boot.esp32s2: SPI Mode       : DIO
I (52) boot.esp32s2: SPI Flash Size : 4MB
I (57) boot: Enabling RNG early entropy source...
I (62) boot: Partition Table:
I (66) boot: ## Label            Usage          Type ST Offset   Length
I (73) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (81) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (88) boot:  2 factory          factory app      00 00 00010000 00100000
I (95) boot: End of partition table
I (100) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=097a8h ( 38824) map
I (117) esp_image: segment 1: paddr=000197d0 vaddr=3ffbe590 size=02ce4h ( 11492) load
I (120) esp_image: segment 2: paddr=0001c4bc vaddr=40022000 size=03b5ch ( 15196) load
I (129) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=1fed4h (130772) map
I (162) esp_image: segment 4: paddr=0003fefc vaddr=40025b5c size=08a30h ( 35376) load
I (171) esp_image: segment 5: paddr=00048934 vaddr=50000000 size=00010h (    16) load
I (178) boot: Loaded app from partition at offset 0x10000
I (179) boot: Disabling RNG early entropy source...
I (192) cac��f<��3?������W��
                            �V�,ZY�B��size 8KB, 4Ways, cache line size 32Byte
I (193) cpu_start: Pro cpu up.
I (204) cpu_start: Pro cpu start user code
I (204) cpu_start: cpu freq: 160000000
I (204) cpu_start: Application information:
I (209) cpu_start: Project name:     provision_test_certificate
I (216) cpu_start: App version:      202005.00-6-gd0d8690-dirty
I (222) cpu_start: Compile time:     Jul  6 2021 13:38:44
I (228) cpu_start: ELF file SHA256:  4a4efcbdc51afc32...
I (234) cpu_start: ESP-IDF:          v4.3-dirty
I (239) heap_init: Initializing. RAM available for dynamic allocation:
I (247) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (253) heap_init: At 3FFC2248 len 00039DB8 (231 KiB): DRAM
I (259) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (266) spi_flash: detected chip: generic
I (270) spi_flash: flash io: dio
I (274) cpu_start: Starting scheduler on PRO CPU.
I (479) pal_os_event: Init : Create Timer
I (479) pal_os_event: Init : Create Timer successful
[optiga util]     : OPTIGA Trust initialization
[optiga util]     : optiga_util_open_application
[optiga cmd]      : optiga_cmd_open_application
I (569) pal_i2c: Initialize pal_i2c_init  
I (569) pal_i2c: init successful
I (579) pal_i2c: W-Failure
I (599) pal_i2c: W-Failure
I (619) pal_i2c: W-Failure
I (639) pal_i2c: W-Failure
I (659) pal_i2c: W-Failure
I (679) pal_i2c: W-Failure
I (699) pal_i2c: W-Failure
I (719) pal_i2c: W-Failure
I (739) pal_i2c: W-Failure
I (759) pal_i2c: W-Failure
I (779) pal_i2c: W-Failure
I (799) pal_i2c: W-Failure
I (819) pal_i2c: W-Failure
I (839) pal_i2c: W-Failure
I (859) pal_i2c: W-Failure
I (879) pal_i2c: W-Failure
I (899) pal_i2c: W-Failure
I (919) pal_i2c: W-Failure
I (939) pal_i2c: W-Failure
I (959) pal_i2c: W-Failure
I (979) pal_i2c: W-Failure
I (999) pal_i2c: W-Failure
I (1019) pal_i2c: W-Failure
I (1039) pal_i2c: W-Failure
I (1059) pal_i2c: W-Failure
I (1079) pal_i2c: W-Failure
I (1099) pal_i2c: W-Failure
I (1119) pal_i2c: W-Failure
I (1139) pal_i2c: W-Failure
I (1159) pal_i2c: W-Failure
I (1179) pal_i2c: W-Failure
I (1199) pal_i2c: W-Failure
I (1219) pal_i2c: W-Failure
I (1239) pal_i2c: W-Failure
I (1259) pal_i2c: W-Failure
I (1279) pal_i2c: W-Failure
I (1299) pal_i2c: W-Failure
I (1319) pal_i2c: W-Failure
I (1339) pal_i2c: W-Failure
I (1359) pal_i2c: W-Failure
I (1379) pal_i2c: W-Failure
I (1399) pal_i2c: W-Failure
I (1419) pal_i2c: W-Failure
I (1439) pal_i2c: W-Failure
I (1459) pal_i2c: W-Failure
I (1479) pal_i2c: W-Failure
I (1499) pal_i2c: W-Failure
I (1519) pal_i2c: W-Failure
I (1539) pal_i2c: W-Failure
I (1559) pal_i2c: W-Failure
I (1579) pal_i2c: W-Failure
I (1599) pal_i2c: W-Failure
I (1619) pal_i2c: W-Failure
I (1639) pal_i2c: W-Failure
I (1659) pal_i2c: W-Failure
I (1679) pal_i2c: W-Failure
I (1699) pal_i2c: W-Failure
I (1719) pal_i2c: W-Failure
I (1739) pal_i2c: W-Failure
I (1759) pal_i2c: W-Failure
I (1779) pal_i2c: W-Failure
I (1799) pal_i2c: W-Failure
I (1819) pal_i2c: W-Failure
I (1839) pal_i2c: W-Failure
I (1859) pal_i2c: W-Failure
I (1879) pal_i2c: W-Failure
I (1899) pal_i2c: W-Failure
I (1919) pal_i2c: W-Failure
I (1939) pal_i2c: W-Failure
I (1959) pal_i2c: W-Failure
I (1979) pal_i2c: W-Failure
I (1999) pal_i2c: W-Failure
I (2019) pal_i2c: W-Failure
I (2039) pal_i2c: W-Failure
I (2059) pal_i2c: W-Failure
I (2079) pal_i2c: W-Failure
I (2099) pal_i2c: W-Failure
I (2119) pal_i2c: W-Failure
I (2139) pal_i2c: W-Failure
I (2159) pal_i2c: W-Failure
I (2179) pal_i2c: W-Failure
I (2199) pal_i2c: W-Failure
I (2219) pal_i2c: W-Failure
I (2239) pal_i2c: W-Failure
I (2259) pal_i2c: W-Failure
I (2279) pal_i2c: W-Failure
I (2299) pal_i2c: W-Failure
I (2319) pal_i2c: W-Failure
I (2339) pal_i2c: W-Failure
I (2359) pal_i2c: W-Failure
I (2379) pal_i2c: W-Failure
I (2399) pal_i2c: W-Failure
I (2419) pal_i2c: W-Failure
I (2439) pal_i2c: W-Failure
I (2459) pal_i2c: W-Failure
I (2479) pal_i2c: W-Failure
I (2499) pal_i2c: W-Failure
I (2519) pal_i2c: W-Failure
I (2539) pal_i2c: W-Failure
I (2559) pal_i2c: W-Failure
I (2579) pal_i2c: W-Failure
I (2599) pal_i2c: W-Failure
I (2619) pal_i2c: W-Failure
I (2639) pal_i2c: W-Failure
I (2659) pal_i2c: W-Failure
I (2679) pal_i2c: W-Failure
I (2699) pal_i2c: W-Failure
I (2719) pal_i2c: W-Failure
I (2739) pal_i2c: W-Failure
I (2759) pal_i2c: W-Failure
I (2779) pal_i2c: W-Failure
I (2799) pal_i2c: W-Failure
I (2819) pal_i2c: W-Failure
I (2839) pal_i2c: W-Failure
I (2859) pal_i2c: W-Failure
I (2879) pal_i2c: W-Failure
I (2899) pal_i2c: W-Failure
I (2919) pal_i2c: W-Failure
I (2939) pal_i2c: W-Failure
I (2959) pal_i2c: W-Failure
I (2979) pal_i2c: W-Failure
I (2999) pal_i2c: W-Failure
I (3019) pal_i2c: W-Failure
I (3039) pal_i2c: W-Failure
I (3059) pal_i2c: W-Failure
I (3079) pal_i2c: W-Failure
I (3099) pal_i2c: W-Failure
I (3119) pal_i2c: W-Failure
I (3139) pal_i2c: W-Failure
I (3159) pal_i2c: W-Failure
I (3179) pal_i2c: W-Failure
I (3199) pal_i2c: W-Failure
I (3219) pal_i2c: W-Failure
I (3239) pal_i2c: W-Failure
I (3259) pal_i2c: W-Failure
I (3279) pal_i2c: W-Failure
I (3299) pal_i2c: W-Failure
I (3319) pal_i2c: W-Failure
I (3339) pal_i2c: W-Failure
I (3359) pal_i2c: W-Failure
I (3379) pal_i2c: W-Failure
I (3399) pal_i2c: W-Failure
I (3419) pal_i2c: W-Failure
I (3439) pal_i2c: W-Failure
I (3459) pal_i2c: W-Failure
I (3479) pal_i2c: W-Failure
I (3499) pal_i2c: W-Failure
I (3519) pal_i2c: W-Failure
I (3539) pal_i2c: W-Failure
I (3559) pal_i2c: W-Failure
I (3579) pal_i2c: W-Failure
I (3599) pal_i2c: W-Failure
I (3619) pal_i2c: W-Failure
I (3639) pal_i2c: W-Failure
I (3659) pal_i2c: W-Failure
I (3679) pal_i2c: W-Failure
I (3699) pal_i2c: W-Failure
I (3719) pal_i2c: W-Failure
I (3739) pal_i2c: W-Failure
I (3759) pal_i2c: W-Failure
I (3779) pal_i2c: W-Failure
I (3799) pal_i2c: W-Failure
I (3819) pal_i2c: W-Failure
I (3839) pal_i2c: W-Failure
I (3859) pal_i2c: W-Failure
I (3879) pal_i2c: W-Failure
I (3899) pal_i2c: W-Failure
I (3919) pal_i2c: W-Failure
I (3939) pal_i2c: W-Failure
I (3959) pal_i2c: W-Failure
I (3979) pal_i2c: W-Failure
I (3999) pal_i2c: W-Failure
I (4019) pal_i2c: W-Failure
I (4039) pal_i2c: W-Failure
I (4059) pal_i2c: W-Failure
I (4079) pal_i2c: W-Failure
I (4099) pal_i2c: W-Failure
I (4119) pal_i2c: W-Failure
I (4139) pal_i2c: W-Failure
I (4159) pal_i2c: W-Failure
I (4179) pal_i2c: W-Failure
I (4199) pal_i2c: W-Failure
I (4219) pal_i2c: W-Failure
I (4239) pal_i2c: W-Failure
I (4259) pal_i2c: W-Failure
I (4279) pal_i2c: W-Failure
I (4299) pal_i2c: W-Failure
I (4319) pal_i2c: W-Failure
I (4339) pal_i2c: W-Failure
I (4359) pal_i2c: W-Failure
I (4379) pal_i2c: W-Failure
I (4399) pal_i2c: W-Failure
I (4419) pal_i2c: W-Failure
I (4439) pal_i2c: W-Failure
I (4459) pal_i2c: W-Failure
I (4479) pal_i2c: W-Failure
I (4499) pal_i2c: W-Failure
I (4519) pal_i2c: W-Failure
I (4539) pal_i2c: W-Failure
I (4559) pal_i2c: W-Failure
I (4579
Select the key type from below list
Press 1 to Generate NIST P-256
Press 2 to Generate NIST P-384
Press 3 to Generate NIST P-521
Press 4 to Generate Brainpool 256 r1
Press 5 to Generate Brainpool 384 r1
Press 6 to Generate Brainpool 512 r1
Press 7 to Generate RSA 1024
Press 8 to Generate RSA 2048

Selected NIST P-256 Curve
Generating keypair in Oid E0F1
[optiga crypt]    : optiga_crypt_ecc_generate_keypair
[optiga cmd]      : optiga_cmd_gen_keypair
[optiga cmd]      : Sending generate keypair command..
[optiga crypt]    : Call back status error
202
Key Pair generation failed
markandpathak commented 3 years ago

The value ret in this if statement is ESP_FAIL which causes else part of the condition to be executed and hence printing w-failure

ayushev commented 3 years ago

The value ret in this if statement is ESP_FAIL which causes else part of the condition to be executed and hence printing w-failure

According to the documentation it means that the slave doesn't acknowedge the transfer which might have different reasons. What typo of baord do you have, is it a Shield2Go or a Chip (USON-10)? Do you have somewhere a reference kit where you can test whether your sample is working correctly, for example the Evaluation Kit, or FTDI USB-I2C Converter Board, or Raspberry Pi

markandpathak commented 3 years ago

It's a custom board with IC(USON-10) soldered into it. May be I need an evaluation kit to know whether it's a hardware issue or not. Although device has a fairly simple circuit. 3.3V to VCC with a dcap, GND to VSS, RST to ESP32-s2 GPIO4 and SCL SDA to GPIO34 GPIO33 respectively. Both SCL, SDA lines have 10k external pullups attached. I also tried to disable internal pullsups in pal_i2c but it also gives same result. Bottom pad is NC.

ayushev commented 3 years ago

alternativly to use any digital/logic analyser to see what happens on the line, this would be actually very helpful. This chip might be damaged during soldering and that might be the reason why it doesn't respond, alternativly it might be some missing configuration on the host side. Another question which is easy to check, what is the RST state, is it possible that it it configured "low"?

markandpathak commented 3 years ago

We have a usb based digital logic analyzer, it will be available tomorrow. Regarding RST pin I checked it for high state and also tied it to high and configuring the optiga lib to warm reset but that also didn't work. Let's see what logic analyzer reveals. I'll go through each configuration once again.

markandpathak commented 3 years ago

I tested the communication on the I2C lines. There is no response from the IC. Screenshot from 2021-07-10 13-39-55 The same address byte is written at the interval of 20ms but no response from the IC. Screenshot from 2021-07-10 13-36-05 RST pin was high all the time. It can be a hardware issue. Any suggestions where I need to look in hardware? As the circuit is exact similar to Shield2Go schematic.

ayushev commented 3 years ago

@markandpathak thanks for the measurements! When you say it is exactly the same, does it mean you also have the VCC control circuit? aIW5x1GmGj

markandpathak commented 3 years ago

No VCC part is not implemented. Vcc is supplied directly without any control. Everything rest is same.

ayushev commented 3 years ago

I tested the communication on the I2C lines. There is no response from the IC. Screenshot from 2021-07-10 13-39-55 The same address byte is written at the interval of 20ms but no response from the IC. Screenshot from 2021-07-10 13-36-05 RST pin was high all the time. It can be a hardware issue. Any suggestions where I need to look in hardware? As the circuit is exact similar to Shield2Go schematic.

is it possble by any chance to get the begginign of this sequence? Ideally with the power line... Trust M takes around 15 ms for the power-up right after the VCC is applied, after this it stays in the active listening state for at least 25 ms. Would be extremely helpful to understand whether the Host tries to reach the chip within this period.

Hardware issue during soldering is not excluded of course, but I'd maybe check it at latest.

markandpathak commented 3 years ago

Ok. I'll check and post the results here.

ayushev commented 3 years ago

any progress here?

markandpathak commented 3 years ago

We had new boards fabricated. this time assembled with precise reflow oven to eliminate possibility of damage while soldering. Still, same issue.

markandpathak commented 3 years ago

There's a surprising observation. Just for experiment we removed both 10k pull up and let the device run by enabling ESP32's internal pullups. Now there's no more I2C write failure. I am able to communicate with the chip. Keys generation fails is a second matter but now I am one step closer as atleast chip is responding. Any idea why this can happen? There are no other devices on I2C bus. Still without pullup the i2c does not respond when I2C clk frequency is more than 100k. From schematic perspective both SCL and SDA lines go straight into MCU pins.

Edit: Prior to removing pull-ups, I have tried with both ESP32 pull-ups enabled and disabled.

markandpathak commented 3 years ago

This is the output now in which key generation fails.

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0xb (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x1830
load:0x4004c000,len:0x9e8
load:0x40050000,len:0x2b70
SHA-256 comparison failed:
Calculated: 301ad638be6160e27efe560514a2e039cafeadf6bc4fb6fecab929e3ff7d58e9
Expected: 8e3e840813e19af230af79254ec30d923bd0cb97442d05668be75b5ffe95f2a4
Attempting to boot anyway...
entry 0x4004c1ec
I (40) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (40) boot: compile time 16:06:08
I (40) boot: chip revision: 0
I (43) boot.esp32s2: SPI Speed      : 80MHz
I (47) boot.esp32s2: SPI Mode       : DIO
I (52) boot.esp32s2: SPI Flash Size : 4MB
I (57) boot: Enabling RNG early entropy source...
I (62) boot: Partition Table:
I (66) boot: ## Label            Usage          Type ST Offset   Length
I (73) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (81) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (88) boot:  2 factory          factory app      00 00 00010000 00100000
I (95) boot: End of partition table
I (100) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=09f08h ( 40712) map
I (117) esp_image: segment 1: paddr=00019f30 vaddr=3ffbe5a0 size=02ce4h ( 11492) load
I (120) esp_image: segment 2: paddr=0001cc1c vaddr=40022000 size=033fch ( 13308) load
I (129) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=20514h (132372) map
I (162) esp_image: segment 4: paddr=0004053c vaddr=400253fc size=09198h ( 37272) load
I (172) esp_image: segment 5: paddr=000496dc vaddr=50000000 size=00010h (    16) load
I (179) boot: Loaded app from partition at offset 0x10000
I (179) boot: Disabling RNG early entropy source...
I (193) cac�fÆ~
               ��3?���\],]Z�
                            �V�,ZY�B��size 8KB, 4Ways, cache line size 32Byte
I (193) cpu_start: Pro cpu up.
I (205) cpu_start: Pro cpu start user code
I (205) cpu_start: cpu freq: 160000000
I (205) cpu_start: Application information:
I (209) cpu_start: Project name:     provision_test_certificate
I (216) cpu_start: App version:      202005.00-6-gd0d8690-dirty
I (222) cpu_start: Compile time:     Aug 23 2021 16:19:43
I (235) cpu_start: ESP-IDF:          v4.3-dirty
I (240) heap_init: Initializing. RAM available for dynamic allocation:
I (247) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (253) heap_init: At 3FFC2258 len 00039DA8 (231 KiB): DRAM
I (259) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (266) spi_flash: detected chip: generic
I (270) spi_flash: flash io: dio
I (275) cpu_start: Starting scheduler on PRO CPU.
I (280) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (380) pal_os_event: Init : Create Timer
I (380) pal_os_event: Init : Create Timer successful
[optiga util]     : OPTIGA Trust initialization
[optiga util]     : optiga_util_open_application
[optiga cmd]      : optiga_cmd_open_application
I (470) pal_i2c: Initialize pal_i2c_init  
I (470) pal_i2c: init successful
I (470) pal_i2c : W:: 84 
I (480) pal_i2c : R:: 00 00 01 90 
I (490) pal_i2c : W:: 81 01 15 
I (500) pal_i2c : W:: 81 
I (510) pal_i2c : R:: 01 15 
[optiga cmd]      : Sending open app command...
[optiga comms]    : >>>>
                    Length of data - 0x001B
                    03 00 16 08 20 F0 00 00 10 D2 76 00 00 04 47 65 6E 41 75 74 68 41 70 70 6C BE 40 

elect the key type from below list
Press 1 to Generate NIST P-256
Press 2 to Generate NIST P-384
Press 3 to Generate NIST P-521
Press 4 to Generate Brainpool 256 r1
Press 5 to Generate Brainpool 384 r1
Press 6 to Generate Brainpool 512 r1
Press 7 to Generate RSA 1024
Press 8 to Generate RSA 2048

Selected NIST P-384 Curve
Generating keypair in Oid E0F2
[optiga crypt]    : optiga_crypt_ecc_generate_keypair
[optiga cmd]      : optiga_cmd_gen_keypair
[optiga cmd]      : Sending generate keypair command..
[optiga comms]    : >>>>
                    Length of data - 0x0014
[optiga crypt]    : Call back status error0 09 01 00 02 E0 F2 02 00 01 11 03 6D 
102
Key Pair generation failed
ayushev commented 3 years ago

I see,

ok the chip on the board is configured to operate on 400 kHz

I (470) pal_i2c : W:: 84 
I (480) pal_i2c : R:: 00 00 01 90

, however 10 kOhm are usually recommended for the 100kHz operation frequency.

Can you please try co configure the communication stack to operate on 100kHz and bring the resistors back, you need to change it here and here

Also it is interesting but there is no

pal_i2c : W:: 80 03 00 15 00 70 00 00 10 D2 76 00 00 04 47 65 6E 41 75 74 68 41 70 70 6C 04 1A
<Several of pal_i2c : W:: 82>
pal_i2c : R:: 48 80 00 0A
pal_i2c : W:: 80
pal_i2c : R:: 00 00 05 00 00 00 00 00 14 87

before the "Select the key pair"

Maybe to have a more clear setup, could you please comment this line out to see whether you have a clear communication for the OpenApplicaiton (this is a prerequisite for the communication). Actually this last command 00 00 05 00 00 00 00 00 14 87 means that the SE is ready to accept commands.

markandpathak commented 3 years ago

Ok, I tried what you suggested by editing the code and with resistors. Following are outcomes: (1) With 10k resistor back in place IC does not respond at 100k or 400k frequency. Same as previous. Tried with both ESP pullup enabled and disabled. (2) We replaced 10k with 4.7k and tried the same. With esp32 pull-ups disabled IC does not respond. With ESP32 pull-ups enabled IC does respond but never outputs the SE ready byte sequence. I can not understand particularly this issue. I have never faced such issue in any of my previous designs involving multiple I2C sensors on same bus.

I changed the frequency to 100k in both files. but still same sequence is received 00 00 01 90 as you mentioned previously.

Here is the output:

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0xb (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x1830
load:0x4004c000,len:0x9e8
load:0x40050000,len:0x2b70
SHA-256 comparison failed:
Calculated: 05b12c3a7d15c2939279d99d73c7eacbafa543325162c6d72dea795769d5eb35
Expected: 61b1924eca2766815c2fb33b1a3b727290fa18a23bacfa1a4d3ee072db500fda
Attempting to boot anyway...
entry 0x4004c1ec
I (40) boot: ESP-IDF v4.3-dirty 2nd stage bootloader
I (40) boot: compile time 13:08:45
I (40) boot: chip revision: 0
I (43) boot.esp32s2: SPI Speed      : 80MHz
I (47) boot.esp32s2: SPI Mode       : DIO
I (52) boot.esp32s2: SPI Flash Size : 4MB
I (57) boot: Enabling RNG early entropy source...
I (62) boot: Partition Table:
I (66) boot: ## Label            Usage          Type ST Offset   Length
I (73) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (81) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (88) boot:  2 factory          factory app      00 00 00010000 00100000
I (95) boot: End of partition table
I (100) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=093f8h ( 37880) map
I (116) esp_image: segment 1: paddr=00019420 vaddr=3ffbe3c0 size=02ce4h ( 11492) load
I (119) esp_image: segment 2: paddr=0001c10c vaddr=40022000 size=03f0ch ( 16140) load
I (129) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=1dc6ch (121964) map
I (160) esp_image: segment 4: paddr=0003dc94 vaddr=40025f0c size=084ach ( 33964) load
I (169) esp_image: segment 5: paddr=00046148 vaddr=50000000 size=00010h (    16) load
I (176) boot: Loaded app from partition at offset 0x10000
I (176) boot: Disabling RNG early entropy source...
I (191) cac�fÆ~
               ��3?������W��
                            �V�,ZY�B��size 8KB, 4Ways, cache line size 32Byte
I (191) cpu_start: Pro cpu up.
I (202) cpu_start: Pro cpu start user code
I (202) cpu_start: cpu freq: 160000000
I (202) cpu_start: Application information:
I (207) cpu_start: Project name:     provision_test_certificate
I (214) cpu_start: App version:      202005.00-6-gd0d8690-dirty
I (220) cpu_start: Compile time:     Aug 24 2021 13:08:40
I (226) cpu_start: ELF file SHA256:  2fb4f1a8f64a403f...
I (232) cpu_start: ESP-IDF:          v4.3-dirty
I (238) heap_init: Initializing. RAM available for dynamic allocation:
I (245) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
I (251) heap_init: At 3FFC2070 len 00039F90 (231 KiB): DRAM
I (257) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
I (264) spi_flash: detected chip: generic
I (268) spi_flash: flash io: dio
I (273) cpu_start: Starting scheduler on PRO CPU.
I (278) gpio: GPIO[4]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (378) pal_os_event: Init : Create Timer
I (378) pal_os_event: Init : Create Timer successful
[optiga util]     : OPTIGA Trust initialization
[optiga util]     : optiga_util_open_application
[optiga cmd]      : optiga_cmd_open_application
I (468) pal_i2c: Initialize pal_i2c_init  
I (468) pal_i2c: init successful
I (468) pal_i2c : W:: 84 
I (478) pal_i2c : R:: 00 00 01 90 
I (488) pal_i2c : W:: 81 01 15 
I (498) pal_i2c : W:: 81 
I (508) pal_i2c : R:: 01 15 
[optiga cmd]      : Sending open app command...
[optiga comms]    : >>>>
                    Length of data - 0x001B
E (5358) task_wdt: Task watchdog got triggered. The following tasks did not reset the watchdog in time:
E (5358) task_wdt:  - IDLE (CPU 0)
E (5358) task_wdt: Tasks currently running:
E (5358) task_wdt: CPU 0: main
E (5358) task_wdt: Print CPU 0 (current core) backtrace

Backtrace:0x4008BE6A:0x3FFBEB60 0x400240EE:0x3FFBEB80 0x40085A50:0x3FFC36C0 0x400859DB:0x3FFC36E0 0x4009DABA:0x3FFC3700 0x4002A5AD:0x3FFC3720 
0x4008be6a: task_wdt_isr at /home/invesun/esp/esp-idf/components/esp_common/src/task_wdt.c:189

0x400240ee: _xt_lowint1 at /home/invesun/esp/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1105

0x40085a50: optiga_trust_init at /home/invesun/UNITGRID/optiga/azure-optiga-trust-m/components/optiga/optiga-trust-m/examples/utilities/optiga_trust.c:614 (discriminator 1)

0x400859db: app_main at /home/invesun/UNITGRID/optiga/azure-optiga-trust-m/examples/provision_test_certificate/build/../main/main.c:472

0x4009daba: main_task at /home/invesun/esp/esp-idf/components/freertos/port/port_common.c:133 (discriminator 2)

0x4002a5ad: vPortTaskWrapper at /home/invesun/esp/esp-idf/components/freertos/port/xtensa/port.c:168

[optiga util]     : optiga_util_open_application failed 00 04 47 65 6E 41 75 74 68 41 70 70 6C BE 40
Youldboukhitine commented 2 years ago

Do you have any concretes outputs ? or help ? I have the same issue do not find a proper way to be acknowledge by the chip.

Thanks

** Update ****

I finally find the root cause, the problem was due to pull up resistor (change from 10k to 4k7) + the implementation of the ESP32 pal i2c more precisely,

Due to the sleep behavior of the Trust M the application code (ESP32 pal i2c) must retry sending the frame when not get acknowledge from the chip.

The function "pal_i2c_write" has been updated with the following code 

pal_status_t pal_i2c_write(const pal_i2c_t *p_i2c_context, uint8_t *p_data, uint16_t length)
{
    pal_status_t status = PAL_STATUS_FAILURE;
    upper_layer_callback_t upper_layer_handler;
    int i2c_master_port;
    esp32_i2c_ctx_t *master_ctx;

    gp_pal_i2c_current_ctx = p_i2c_context;

    if ((p_i2c_context == NULL) || (p_i2c_context->p_i2c_hw_config == NULL))
        return status;

    master_ctx = (esp32_i2c_ctx_t *)p_i2c_context->p_i2c_hw_config;
    i2c_master_port = master_ctx->port;
    int i = 0;
    esp_err_t ret;
    do
    {
        i2c_cmd_handle_t cmd = i2c_cmd_link_create();

        i2c_master_start(cmd);
        i2c_master_write_byte(cmd, (p_i2c_context->slave_address << 1) | WRITE_BIT, ACK_CHECK_EN);
        i2c_master_write(cmd, p_data, length, ACK_CHECK_EN);
        i2c_master_stop(cmd);
         ret = i2c_master_cmd_begin(i2c_master_port, cmd, 20 / portTICK_RATE_MS);
        i2c_cmd_link_delete(cmd);

        upper_layer_handler = (upper_layer_callback_t)p_i2c_context->upper_layer_event_handler;

        vTaskDelay(pdMS_TO_TICKS(2));

        i++;

    } while(i<100 && ret != ESP_OK);

    if (ret == ESP_OK)
    {
        upper_layer_handler(p_i2c_context->p_upper_layer_ctx, PAL_I2C_EVENT_SUCCESS);
        status = PAL_STATUS_SUCCESS;
    }
    else
    {
        upper_layer_handler(p_i2c_context->p_upper_layer_ctx, PAL_I2C_EVENT_ERROR);
    }

    return status;
}

@ayushev shall I create a PR for the update ?