malformedProtobuf with BLE provision example IDF V3.2

[RMandR]

I'm trying to use the IDF version 3.2 ble provisioning example with the IO sample app under security 1.

It finds the ESP32 device successfully and passes the credentials:

I (42728) app_prov_handler: WiFi Credentials Received :
ssid myssid
password mypassword
E (42868) WiFiProvConfig: Unable to unpack config data
E (42868) protocomm: Request handler for prov-config failed
E (42878) protocomm_ble: Invalid content received, killing connection

The provisioning never completes and on the ios app I get a "malformedProtobuf" error on the IOS app. Although the errors seem to happen only on one side (either ios produces the protobuf error or the esp32, but not both at the same time).

Is there something else I need to set with protocol buffers (end points, etc) before running the app?

[ESP_anuj]

Looks like there is a mismatch between the protobuf files on iOS and ESP32. Can you share the complete logs for iOS and ESP32?

Can you also share the version of protoc-gen-swift that you have installed? You can find it by typing `protoc-gen-swift --version`.
There are some known issues for the swift-protobuf library from Apple with Swift5, so hopefully this is not an issue related to that.

[RMandR]

Hi Anuj,

Thanks for looking into this. Below are the logs from esp32 and xcode console. In the example below, the ios app complained about the protobuf. In some cases (e.g. my original post) esp32 produces the error.

It seems that the project is set to compile with Swift 4.2. So hopefully no breakage due to Swift 5 issues.

protoc-gen-swift --version reports

protoc-gen-swift 1.3.1

so this is the different from the prescribed 1.1.1.

I don't know how to easily downgrade protobuf using brew. Though I'm assuming these libraries are backward compatible, no?

Here's the complete output from ESP32:

Code: Select all

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 188777542, 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:0x3fff0018,len:4
load:0x3fff001c,len:6200
load:0x40078000,len:10180
load:0x40080400,len:6640
entry 0x40080760
I (29) boot: ESP-IDF v3.2 2nd stage bootloader
I (29) boot: compile time 12:02:34
I (29) boot: Enabling RNG early entropy source...
I (34) boot: SPI Speed      : 40MHz
I (38) boot: SPI Mode       : DIO
I (42) boot: SPI Flash Size : 4MB
I (46) boot: Partition Table:
I (50) boot: ## Label            Usage          Type ST Offset   Length
I (57) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (64) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (72) boot:  2 factory          factory app      00 00 00010000 00124f80
I (79) boot: End of partition table
I (83) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x2f6a0 (194208) map
I (160) esp_image: segment 1: paddr=0x0003f6c8 vaddr=0x3ffbdb60 size=0x00948 (  2376) load
I (162) esp_image: segment 2: paddr=0x00040018 vaddr=0x400d0018 size=0xbf698 (784024) map
I (442) esp_image: segment 3: paddr=0x000ff6b8 vaddr=0x3ffbe4a8 size=0x02870 ( 10352) load
I (446) esp_image: segment 4: paddr=0x00101f30 vaddr=0x40080000 size=0x00400 (  1024) load
I (449) esp_image: segment 5: paddr=0x00102338 vaddr=0x40080400 size=0x162f8 ( 90872) load
I (508) boot: Loaded app from partition at offset 0x10000
I (508) boot: Disabling RNG early entropy source...
I (509) cpu_start: Pro cpu up.
I (512) cpu_start: Starting app cpu, entry point is 0x4008102c
I (0) cpu_start: App cpu up.
I (522) heap_init: Initializing. RAM available for dynamic allocation:
I (529) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (535) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (541) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (548) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM
I (554) heap_init: At 3FFCDCE0 len 00012320 (72 KiB): DRAM
I (560) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (566) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (573) heap_init: At 400966F8 len 00009908 (38 KiB): IRAM
I (579) cpu_start: Pro cpu start user code
I (261) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (348) wifi: wifi driver task: 3ffd13e8, prio:23, stack:3584, core=0
I (348) wifi: wifi firmware version: 9415913
I (348) wifi: config NVS flash: enabled
I (348) wifi: config nano formating: disabled
I (358) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (368) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (398) wifi: Init dynamic tx buffer num: 32
I (398) wifi: Init data frame dynamic rx buffer num: 32
I (398) wifi: Init management frame dynamic rx buffer num: 32
I (398) wifi: Init static rx buffer size: 1600
I (408) wifi: Init static rx buffer num: 10
I (408) wifi: Init dynamic rx buffer num: 32
I (418) app: Starting BLE provisioning
I (418) BTDM_INIT: BT controller compile version [ae47c48]
I (428) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (498) phy: phy_version: 4008, c9ae59f, Jan 25 2019, 16:54:06, 0, 0
I (888) app_prov: Provisioning started with BLE devname : PROV_611158
I (888) app_prov: BLE Provisioning started
I (53128) app_prov_handler: WiFi Credentials Received :
        ssid myssid
        password mypassword

And here's the complete output from the iOS app:

Code: Select all

Bluetooth state on
2019-04-25 09:38:28.837296-0400 EspressifProvision[389:74186] [MC] System group container for systemgroup.com.apple.configurationprofiles path is /private/var/containers/Shared/SystemGroup/systemgroup.com.apple.configurationprofiles
2019-04-25 09:38:28.838738-0400 EspressifProvision[389:74186] [MC] Reading from public effective user settings.
2019-04-25 09:38:41.339695-0400 EspressifProvision[389:74186] [Snapshotting] Snapshotting a view (0x100e56d60, _UIReplicantView) that has not been rendered at least once requires afterScreenUpdates:YES.
2019-04-25 09:38:45.130946-0400 EspressifProvision[389:74186] [Snapshotting] Snapshotting a view (0x100f64640, _UIReplicantView) that has not been rendered at least once requires afterScreenUpdates:YES.
malformedProtobuf

[ESP_anuj]

I was able to reproduce your issue using Version 10.2.1 (10E1001) of Xcode, with the compiler that is part of it. It threw quite a few warnings for me when building, so I think the issue here is that some of those are actually breaking things. The temporary solution to this is to use the older version of Xcode with it's older 4.2 Swift toolchain with the 3.2 release of IDF and the present release of the iOS app on GitHub.

The better fix will take a little work on my end - we will have a new release for only the iOS for Swift 5.

Can you just verify for me that you are indeed using 10.2.1 Xcode?

[RMandR]

I was able to reproduce your issue using Version 10.2.1 (10E1001) of Xcode

Nice! Thanks for reproduction.

Can you just verify for me that you are indeed using 10.2.1 Xcode?

I'm using both Version 10.2 (10E125), and I believe 10.2.1 (10E1001) on another machine.

You're right, there are quite a few warnings.

Would this issue not affect potentially everyone using swift-protobuf package with x-code 10.2.x?

[ESP_anuj]

https://github.com/apple/swift-protobuf/pull/843
There are some more issues where people have reported that it doesn't work with the new swift version

The good news is that they have an updated pod release which works without any changes in the app repo. Same goes for the Curve25519 pod, it has an updated release as well.

The bad news is that I still get a malformedProtobuf after this so there might be an issue in the glue layer between the app and the protobuf library which isn't exactly apparent. Hopefully I'll be able to get a patch out for it by end of this week.

[RMandR]

there might be an issue in the glue layer between the app and the protobuf library which isn't exactly apparent. Hopefully I'll be able to get a patch out for it by end of this week

Has there been an update on this? We're sort of stuck at this stage on our side.

[ESP_anuj]

Unfortunately not, but we are very actively working on a fix.

Turns out that this is not a swift 5 issue but something related to our AES security layer.
The issue as it turns out is that the function that actually encrypts using AES CTR (inside aes.c) and the iOS version that is being used don't go well together. Somethings changed on the OS front that is making things incompatible, and that's proving to be trickier to debug.

It works if
- you use the same source on an older iOS using an older Xcode.
- it works for security 0

One suggestion that I can give you is to use security0 for the time being and later this week we should be able to give you something where in you can go back to using security1.

Apologies for the delay in getting a fix out for this!

[RMandR]

it works for security 0

That was going to be my question. Thanks for the update.

I guess using CommonCrypto is out of question? it does support AES-CTR.

[ESP_anuj]

Indeed! We just migrated to CommonCrypto today - and it all works fine now. We are doing some cleanup and testing, but we have a working solution now