Bluetooth scan causes boot loop

bbb · August 22, 2019, 7:27pm

My goal is to scan for classic Bluetooth devices and visualise their MAC addresses.
My actions are:

I set up a very simple library as part of my app that for now should just start the scan.

The code is:

#include "esp32_bt.h"
#include "mgos_bt_gap.h"
#include "mgos.h"


enum mgos_app_init_result mgos_bt_scanner_init(void) {
    { /* Set up the BLE. */
        struct mgos_bt_gap_scan_opts opts = {60000, 1};
        mgos_bt_gap_scan(&opts);
    }
    return MGOS_APP_INIT_SUCCESS;
}

The result I see is:

The device is stuck in a boot loop, it does perform the scan but it immediately reboots.

[Aug 22 20:13:55.393] rst:0xc (SW_CPU_RESET),boot:0x17 (SPI_FAST_FLASH_BOOT)
[Aug 22 20:13:55.393] configsip: 0, SPIWP:0xee
[Aug 22 20:13:55.393] clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[Aug 22 20:13:55.393] mode:DIO, clock div:1
[Aug 22 20:13:55.393] load:0x3fff0018,len:4
[Aug 22 20:13:55.393] load:0x3fff001c,len:6188
[Aug 22 20:13:55.393] load:0x40078000,len:9588
[Aug 22 20:13:55.399] load:0x40080400,len:6968
[Aug 22 20:13:55.399] entry 0x40080740
[Aug 22 20:13:55.423] I (29) boot: ESP-IDF v3.2-r7 2nd stage bootloader
[Aug 22 20:13:55.423] I (29) boot: compile time 19:12:41
[Aug 22 20:13:55.423] I (29) boot: Enabling RNG early entropy source…
[Aug 22 20:13:55.423] I (34) qio_mode: Enabling default flash chip QIO
[Aug 22 20:13:55.423] I (39) boot: SPI Speed : 80MHz
[Aug 22 20:13:55.445] I (43) boot: SPI Mode : QIO
[Aug 22 20:13:55.445] I (47) boot: SPI Flash Size : 4MB
[Aug 22 20:13:55.445] I (51) boot: Partition Table:
[Aug 22 20:13:55.445] I (55) boot: ## Label Usage Type ST Offset Length Flags
[Aug 22 20:13:55.445] I (63) boot: 0 nvs WiFi data 01 02 00009000 00004000 00000000
[Aug 22 20:13:55.468] I (71) boot: 1 otadata OTA data 01 00 0000d000 00002000 00000000
[Aug 22 20:13:55.468] I (79) boot: 2 app_0 OTA app 00 10 00010000 00180000 00000000
[Aug 22 20:13:55.490] I (87) boot: 3 fs_0 SPIFFS 01 82 00190000 00040000 00000000
[Aug 22 20:13:55.490] I (96) boot: 4 app_1 OTA app 00 11 001d0000 00180000 00000000
[Aug 22 20:13:55.490] I (104) boot: 5 fs_1 SPIFFS 01 82 00350000 00040000 00000000
[Aug 22 20:13:55.512] I (112) boot: End of partition table
[Aug 22 20:13:55.512] I (117) boot: OTA data 0: seq 0x00000001, st 0x10, CRC 0x157a2b85, valid? 1
[Aug 22 20:13:55.512] I (124) boot: OTA data 1: seq 0x00000000, st 0x00, CRC 0x00000000, valid? 0
[Aug 22 20:13:55.523] I (132) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x4598c (285068) map
[Aug 22 20:13:55.612] I (219) esp_image: segment 1: paddr=0x000559b4 vaddr=0x3ffbdb60 size=0x0444c ( 17484) load
[Aug 22 20:13:55.612] I (224) esp_image: segment 2: paddr=0x00059e08 vaddr=0x40080000 size=0x00400 ( 1024) load
[Aug 22 20:13:55.612] I (226) esp_image: segment 3: paddr=0x0005a210 vaddr=0x40080400 size=0x05e00 ( 24064) load
[Aug 22 20:13:55.625] I (242) esp_image: segment 4: paddr=0x00060018 vaddr=0x400d0018 size=0x114c88 (1133704) map
[Aug 22 20:13:55.932] I (552) esp_image: segment 5: paddr=0x00174ca8 vaddr=0x40086200 size=0x1096c ( 67948) load
[Aug 22 20:13:55.954] I (574) esp_image: segment 6: paddr=0x0018561c vaddr=0x400c0000 size=0x00034 ( 52) load
[Aug 22 20:13:55.981] I (588) boot: Loaded app from partition at offset 0x10000
[Aug 22 20:13:55.981] I (588) boot: Disabling RNG early entropy source…
[Aug 22 20:13:55.981] I (589) cpu_start: Pro cpu up.
[Aug 22 20:13:55.981] I (592) cpu_start: Single core mode
[Aug 22 20:13:55.981] I (597) heap_init: Initializing. RAM available for dynamic allocation:
[Aug 22 20:13:56.003] I (604) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
[Aug 22 20:13:56.003] I (610) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
[Aug 22 20:13:56.003] I (616) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
[Aug 22 20:13:56.026] I (622) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM
[Aug 22 20:13:56.026] I (628) heap_init: At 3FFD1E88 len 0000E178 (56 KiB): DRAM
[Aug 22 20:13:56.026] I (634) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM
[Aug 22 20:13:56.026] I (640) heap_init: At 40078000 len 00008000 (32 KiB): IRAM
[Aug 22 20:13:56.040] I (647) heap_init: At 40096B6C len 00009494 (37 KiB): IRAM
[Aug 22 20:13:56.040] I (653) cpu_start: Pro cpu start user code
[Aug 22 20:13:56.048] I (334) cpu_start: Starting scheduler on PRO CPU.
[Aug 22 20:13:56.079]
[Aug 22 20:13:56.079]
[Aug 22 20:13:56.079] mgos_freertos.c:175 BluetoothTest 1.0 (20190822-191254/v1.0-2-gf236ca2-master-dirty)
[Aug 22 20:13:56.079] mgos_freertos.c:177 Mongoose OS 2.15.0 (20190822-191254/2.15.0-g787ac38-master)
[Aug 22 20:13:56.079] mgos_freertos.c:181 CPU: 160 MHz, FreeRTOS 8.2.0, heap: 211356 total, 179552 free
[Aug 22 20:13:56.087] mgos_freertos.c:183 Newlib 2.2.0
[Aug 22 20:13:56.087] esp32_main.c:116 ESP-IDF v3.2-r7
[Aug 22 20:13:56.092] esp32_main.c:119 Boot partition: app_0; flash: 4M
[Aug 22 20:13:56.096] mg_lwip_ev_mgr.c:93 Mongoose 6.15, LwIP 2.0.3
[Aug 22 20:13:56.101] mg_ssl_if_mbedtls.c:57 mbed TLS 2.16.0-cesanta4
[Aug 22 20:13:56.107] esp32_fs_crypt.c:82 FS encryption key set up, seed @ 0x0
[Aug 22 20:13:56.114] mgos_vfs_dev.c:73 fs_0: esp32part ({“label”: “fs_0”}), size 262144
[Aug 22 20:13:56.120] mgos_vfs_dev.c:73 fs_1: esp32part ({“label”: “fs_1”}), size 262144
[Aug 22 20:13:56.129] mgos_vfs.c:147 /: SPIFFS @ fs_0, opts {“bs”: 4096, “ps”: 256, “es”: 4096, “encr”: true}
[Aug 22 20:13:56.544] mgos_vfs.c:320 /: size 233681, used: 119727, free: 113954
[Aug 22 20:13:56.625] mgos_sys_config.c:368 MAC: 84:0d:8e:3d:4a:64
[Aug 22 20:13:56.629] mgos_sys_config.c:376 WDT: 30 seconds
[Aug 22 20:13:56.633] mgos_deps_init.c:150 init i2c…
[Aug 22 20:13:56.642] esp32_i2c_master.c:402 I2C0 init ok (SDA: 21, SCL: 22, freq: 100000)
[Aug 22 20:13:56.645] mgos_deps_init.c:150 init atca…
[Aug 22 20:13:56.648] mgos_deps_init.c:150 init mqtt…
[Aug 22 20:13:56.652] mgos_deps_init.c:150 init shadow…
[Aug 22 20:13:56.655] mgos_deps_init.c:150 init aws…
[Aug 22 20:13:56.660] mgos_aws.c:40 AWS Greengrass enable (0)
[Aug 22 20:13:56.664] mgos_deps_init.c:150 init bt-common…
[Aug 22 20:13:56.670] I (1577) BTDM_INIT: BT controller compile version [d53bd19]
[Aug 22 20:13:56.730] I (1637) phy: phy_version: 4008, 544f89f, Jan 24 2019, 14:54:06, 0, 0
[Aug 22 20:13:57.053] esp32_bt_gattc.c:150 REG if 3 st 0 app 0
[Aug 22 20:13:57.059] esp32_bt_gap.c:372 SET_LOCAL_PRIVACY_COMPLETE st 0
[Aug 22 20:13:57.063] esp32_bt_gatts.c:752 REG if 4 st 0 app 0
[Aug 22 20:13:57.071] esp32_bt.c:177 Bluetooth init ok, MTU 500, pairing enabled, 0 paired devices
[Aug 22 20:13:57.076] mgos_deps_init.c:150 init bt-service-config…
[Aug 22 20:13:57.087] esp32_bt_gatts.c:909 CREAT_ATTR_TAB st 0 svc_uuid 5f6d4f53-5f43-4647-5f53-56435f49445f nh 7 hh 0x3ffc2180
[Aug 22 20:13:57.093] esp32_bt_gatts.c:163 esp_ble_gatts_create_attr_tab 0x3ffb9ca0 7 0
[Aug 22 20:13:57.097] mgos_deps_init.c:150 init mjs…
[Aug 22 20:13:57.104] mos_mjs.c:101 mJS memory stat: before init: 153008 after init: 151608
[Aug 22 20:13:57.109] mgos_deps_init.c:150 init bt-scanner…
[Aug 22 20:13:57.115] esp32_bt_gap.c:241 ESP_GAP_BLE_SCAN_PARAM_SET_COMPLETE st 0
[Aug 22 20:13:57.121] esp32_bt_gap.c:189 ESP_GAP_BLE_SCAN_START_COMPLETE st 0
[Aug 22 20:13:57.126] esp32_bt_gap.c:174 Starting scan (active, 80/160)
[Aug 22 20:13:57.131] mgos_deps_init.c:152 bt-scanner init failed
[Aug 22 20:13:57.145] esp32_bt_gap.c:223 SCAN_RESULT 0 c4:1b:0e:ea:46:0c [] dt 2 at 1 et 0 rssi -58 adl 6 [020104020af8] srl 10 [090942202d204465736b]
[Aug 22 20:13:57.149] mgos_freertos.c:204 MGOS init failed: -32
[Aug 22 20:13:57.152] mgos_ota_core.c:967 0 0
[Aug 22 20:13:57.180] esp32_bt_gap.c:223 SCAN_RESULT 0 dd:92:5a:df:d9:4a [] dt 2 at 1 et 0 rssi -63 adl 31 [02010603039afe17169afe000dfb51172d9f0458c0528ccd56838a3be4a440] srl 0 []
[Aug 22 20:13:57.250] esp32_bt_gap.c:223 SCAN_RESULT 0 c4:1b:0e:ea:46:0c [] dt 2 at 1 et 0 rssi -58 adl 6 [020104020af8] srl 10 [090942202d204465736b]
[Aug 22 20:13:57.264] esp32_bt_gap.c:223 SCAN_RESULT 0 ee:de:d8:54:34:1d [] dt 2 at 1 et 3 rssi -41 adl 30 [02010403039afe16169afe1191cf09ee7f6f4e45e9a3c26c35eeff29c902] srl 0 []
[Aug 22 20:13:57.278] esp32_bt_gap.c:223 SCAN_RESULT 0 d5:35:bc:c5:c1:50 [] dt 2 at 1 et 3 rssi -55 adl 30 [02010403039afe16169afe1134153192aa09f602a24a5e3432705206c102] srl 0 []
[Aug 22 20:13:57.293] esp32_bt_gap.c:223 SCAN_RESULT 0 ed:31:dc:1e:c5:97 [] dt 2 at 1 et 3 rssi -53 adl 30 [0201061aff4c000215e1f54e021e2344e09c3d512eb56adec900640064b9] srl 0 []
[Aug 22 20:13:57.352] esp32_bt_gap.c:223 SCAN_RESULT 0 c4:1b:0e:ea:46:0c [] dt 2 at 1 et 0 rssi -63 adl 6 [020104020af8] srl 10 [090942202d204465736b]
[Aug 22 20:13:57.385] esp32_bt_gap.c:223 SCAN_RESULT 0 ec:90:89:1a:43:5a [] dt 2 at 1 et 3 rssi -70 adl 30 [0201061aff4c000215e1f54e021e2344e09c3d512eb56adec900640064b9] srl 0 []
[Aug 22 20:13:57.464] esp32_bt_gap.c:223 SCAN_RESULT 0 39:ac:99:b8:3e:15 [] dt 2 at 1 et 3 rssi -87 adl 31 [1eff0600010920027e8adbd66d6b46c02e9240f1611f83cec1c2b5e3b5ab0f] srl 0 []
[Aug 22 20:13:57.478] esp32_bt_gap.c:223 SCAN_RESULT 0 ee:de:d8:54:34:1d [] dt 2 at 1 et 3 rssi -38 adl 30 [02010403039afe16169afe1191cf09ee7f6f4e45e9a3c26c35eeff29c901] srl 0 []
[Aug 22 20:13:57.493] esp32_bt_gap.c:223 SCAN_RESULT 0 d5:35:bc:c5:c1:50 [] dt 2 at 1 et 3 rssi -55 adl 30 [02010403039afe16169afe1134153192aa09f602a24a5e3432705206c101] srl 0 []
[Aug 22 20:13:57.505] esp32_bt_gap.c:223 SCAN_RESULT 0 c4:1b:0e:ea:46:0c [] dt 2 at 1 et 0 rssi -58 adl 6 [020104020af8] srl 10 [090942202d204465736b]
[Aug 22 20:13:57.574] esp32_bt_gap.c:223 SCAN_RESULT 0 ec:ef:f5:b5:fa:80 [] dt 2 at 1 et 3 rssi -46 adl 30 [0201061aff4c000215e1f54e021e2344e09c3d512eb56adec900640064b9] srl 0 []
[Aug 22 20:13:57.586] esp32_bt_gap.c:223 SCAN_RESULT 0 c4:1b:0e:ea:46:0c [] dt 2 at 1 et 0 rssi -59 adl 6 [020104020af8] srl 10 [090942202d204465736b]
[Aug 22 20:13:57.656] mgos_event.c:135 ev MOS2 triggered 0 handlers
[Aug 22 20:13:57.661] mgos_vfs.c:990 Unmounting filesystems
[Aug 22 20:13:57.664] mgos_vfs_dev.c:203 fs_0 refs 1
[Aug 22 20:13:57.668] mgos_vfs_dev.c:203 fs_1 refs 0
[Aug 22 20:13:57.683] esp32_bt_gap.c:223 SCAN_RESULT 0 ee:de:d8:54:34:1d [] dt 2 at 1 et 3 rssi -52 adl 30 [02010403039afe16169afe1191cf09ee7f6f4e45e9a3c26c35eeff29c903] srl 0 []
[Aug 22 20:13:57.686] mgos_vfs_dev.c:203 fs_0 refs 0
[Aug 22 20:13:57.689] mgos_system.c:42 Restarting
[Aug 22 20:13:57.712] ets Jun 8 2016 00:22:57

My expectation & question is:

It this an MGOS issue or am I doing something wrong?

I tried using the ESP-IDF Bluetooth API as well but couldn’t import components. If I tried using it together with the bt-common library then it would fail to initiate due to an invalid state.

nliviu · August 23, 2019, 3:08am

[Aug 22 20:13:57.109] mgos_deps_init.c:150 init bt-scanner…
...
[Aug 22 20:13:57.131] mgos_deps_init.c:152 bt-scanner init failed
...
[Aug 22 20:13:57.149] mgos_freertos.c:204 MGOS init failed: -32
...
[Aug 22 20:13:57.689] mgos_system.c:42 Restarting

The bt-scanner library fails to initialize, hence the restart.

bbb · August 23, 2019, 10:50am

Thanks for the reply. I don’t understand why it fails to initialise, I even tried removing the code from the init function and simply returning MGOS_APP_INIT_SUCCESS and it still says it failed.

bbb · August 23, 2019, 11:15am

Solved by reflashing with a clean build and waiting longer before opening the console.

I guess the ESP did not like the console being opened right after flashing with encryption.

nliviu · August 23, 2019, 3:11pm

The signature for mgos_bt_scanner_init should be bool mgos_bt_scanner_init(void).
It should return true for success, false for fail.
MGOS_APP_INIT_SUCCESS translates to 0==false, fail.

bool mgos_bt_scanner_init(void) {
    { /* Set up the BLE. */
        struct mgos_bt_gap_scan_opts opts = {60000, 1};
        mgos_bt_gap_scan(&opts);
    }
    return true;
}

Ref: https://github.com/mongoose-os-libs/empty