[Bug]: Panic: can't encode protobuf reason='unterminated string'

[mhcerri]

Category

BLE

Hardware

DIY

Firmware Version

2.5.22.9b46cb4ef086

Description

I'm experiment with some DIY devices but I'm having problems in the communication between the device and the Android app via bluetooth. The information I'm providing here was obtained using the meshtastic-diy-v1_1 environment with an ESP32 devkit, a RA-02 radio and an OLED display. But I faced the same issue with a custom variant using and ESP32-C3 too.

The radio and the OLED display work fine and I can configure the device and set its region without any problems using the CLI tool. The device sees other device and its seen by them.

When using the Android App, the device shows in the screen the paring code and I can pair with the device without any problem. After that, when I connect to device I get no error but the text box for the device name is empty. If I try to change its name or its region nothing happens.

In a similar way, I can got to the "Radio Configuration" screen in the App, but if I click to any of the settings the only things I get is a popup window with a "Close" button, nothing else.

Check the device serial with the CLI tool, I notice the following error message at the exact moment I connect to the device via bluetooth:

ERROR | ??:??:?? 17 Panic: can't encode protobuf reason='unterminated string'

I'm compiling and uploading the master branch from the firmware repository with the following commands:

$ platformio run -e meshtastic-diy-v1_1 -t upload --upload-port /dev/ttyUSB1

And I'm ensuring I have all the proper submodules with:

$ git submodule update --init --recursive

Bellow I'm adding the full serial console output.

Relevant log output

$ meshtastic --port /dev/ttyUSB1 --noproto
WARNING file:mesh_interface.py _sendToRadio line:1118 Not sending packet because protocol use is disabled by noProto
Connected to radio
ets Jul 29 2019 12:21:46

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:1184
load:0x40078000,len:13232
load:0x40080400,len:3028
entry 0x400805e4
E (836) esp_core_dump_flash: No core dump?????????found!
E (836) esp_core_dump_flash: No core dump partition found!
[    11][D][esp32-hal-cpu.c:244] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz
WARNING file:mesh_interface.py _sendToRadio line:1118 Not sending packet because protocol use is disabled by noProto
INFO  | ??:??:?? 0 

//\ E S H T /\ S T / C

INFO  | ??:??:?? 0 Booted, wake cause 0 (boot count 1), reset_reason=reset
DEBUG | ??:??:?? 0 Filesystem files (16384/1048576 Bytes):
DEBUG | ??:??:?? 0  /prefs/channels.proto (57 Bytes)
DEBUG | ??:??:?? 0  /prefs/config.proto (164 Bytes)
DEBUG | ??:??:?? 0  /prefs/db.proto (371 Bytes)
DEBUG | ??:??:?? 0  /prefs/device.proto (96 Bytes)
DEBUG | ??:??:?? 0  /prefs/nodes.proto (277 Bytes)
[   191][I][esp32-hal-i2c.c:75] i2cInit(): Initialising I2C Master: sda=21 scl=22 freq=100000
DEBUG | ??:??:?? 0 Power::lipoInit lipo sensor is not ready yet
INFO  | ??:??:?? 0 Scan for i2c devices
[   208][W][Wire.cpp:301] begin(): Bus already started in Master Mode.
DEBUG | ??:??:?? 0 Scan for I2C devices on port 1
INFO  | ??:??:?? 0 SSD1306 found at address 0x3c
INFO  | ??:??:?? 0 SSD1306 found at address 0x3c
DEBUG | ??:??:?? 0 0x3 subtype probed in 2 tries 
INFO  | ??:??:?? 0 1 I2C devices found
DEBUG | ??:??:?? 0 acc_info = 0
INFO  | ??:??:?? 0 S:B:39,2.5.22.9b46cb4ef086
DEBUG | ??:??:?? 0 Total heap: 195912
DEBUG | ??:??:?? 0 Free heap: 160804
DEBUG | ??:??:?? 0 Total PSRAM: 0
DEBUG | ??:??:?? 0 Free PSRAM: 0
DEBUG | ??:??:?? 0 NVS: UsedEntries 98, FreeEntries 532, AllEntries 630, NameSpaces 4
DEBUG | ??:??:?? 0 Setup Preferences in Flash Storage
DEBUG | ??:??:?? 0 Number of Device Reboots: 19
ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x105 (ESP_ERR_NOT_FOUND) at 0x4009767f
file: "src/platform/esp32/BleOta.cpp" line 16
func: static const esp_partition_t* BleOta::findEspOtaAppPartition()
expression: esp_ota_get_partition_description(part, &app_desc)
ESP_ERROR_CHECK_WITHOUT_ABORT failed: esp_err_t 0x102 (ESP_ERR_INVALID_ARG) at 0x4009767f
file: "src/platform/esp32/BleOta.cpp" line 30
func: static String BleOta::getOtaAppVersion()
expression: esp_ota_get_partition_description(part, &app_desc)
INFO  | ??:??:?? 0 No OTA firmware available
INFO  | ??:??:?? 0 Init NodeDB
[   364][E][vfs_api.cpp:105] open(): /littlefs/static/static does not exist, no permits for creation
INFO  | ??:??:?? 0 Load /prefs/db.proto
INFO  | ??:??:?? 0 Loaded /prefs/db.proto successfully
INFO  | ??:??:?? 0 Loaded saved devicestate version 23, with nodecount: 1
INFO  | ??:??:?? 0 Load /prefs/config.proto
INFO  | ??:??:?? 0 Loaded /prefs/config.proto successfully
INFO  | ??:??:?? 0 Loaded saved config version 24
[   448][E][vfs_api.cpp:105] open(): /littlefs/prefs/module.proto does not exist, no permits for creation
ERROR | ??:??:?? 0 Could not open / read /prefs/module.proto
INFO  | ??:??:?? 0 Install default ModuleConfig
INFO  | ??:??:?? 0 Load /prefs/channels.proto
INFO  | ??:??:?? 0 Loaded /prefs/channels.proto successfully
INFO  | ??:??:?? 0 Loaded saved channelFile version 24
[   499][E][vfs_api.cpp:105] open(): /littlefs/prefs/uiconfig.proto does not exist, no permits for creation
ERROR | ??:??:?? 0 Could not open / read /prefs/uiconfig.proto
DEBUG | ??:??:?? 0 cleanupMeshDB purged 0 entries
DEBUG | ??:??:?? 0 Use nodenum 0xe3ca9dfc 
DEBUG | ??:??:?? 0 Number of Device Reboots: 19
DEBUG | ??:??:?? 0 Expand short PSK #1
INFO  | ??:??:?? 0 Wanted region 0, using UNSET
DEBUG | ??:??:?? 0 Coerce telemetry to min of 30 minutes on defaults
DEBUG | ??:??:?? 0 Opening /prefs/db.proto, fullAtomic=0
INFO  | ??:??:?? 0 Save /prefs/db.proto
DEBUG | ??:??:?? 0 Use GPIO02 for button
DEBUG | ??:??:?? 0 SPI.begin(SCK=18, MISO=19, MOSI=23, NSS=5)
DEBUG | ??:??:?? 0 Use compiled/slipstreamed tzplaceholder                                         
DEBUG | ??:??:?? 0 Set Timezone to GMT0
DEBUG | ??:??:?? 0 Read RTC time as 0
INFO  | ??:??:?? 0 GPS power state move from OFF to ACTIVE
DEBUG | ??:??:?? 0 Use GPIO15 for GPS RX
DEBUG | ??:??:?? 0 Use GPIO0 for GPS TX
DEBUG | ??:??:?? 0 NeighborInfoModule is disabled
DEBUG | ??:??:?? 0 Rescan for I2C keyboard
DEBUG | ??:??:?? 0 Scan for I2C devices on port 1
DEBUG | ??:??:?? 0 Scan address 0x1f
DEBUG | ??:??:?? 0 Scan address 0x55
DEBUG | ??:??:?? 0 Scan address 0x5a
DEBUG | ??:??:?? 0 Scan address 0x5f
INFO  | ??:??:?? 0 External Notification Module Disabled
INFO  | ??:??:?? 0 Turn on screen
DEBUG | ??:??:?? 0 haveGlyphs=1
DEBUG | ??:??:?? 0 waypoint wants a UI Frame
DEBUG | ??:??:?? 0 canned wants a UI Frame
DEBUG | ??:??:?? 0 RF95Interface(cs=5, irq=26, rst=27, busy=33)
INFO  | ??:??:?? 0 Start meshradio init
INFO  | ??:??:?? 0 Radio freq=906.875, config.lora.frequency_offset=0.000
INFO  | ??:??:?? 0 Set radio: region=UNSET, name=LongFast, config=0, ch=19, power=30
INFO  | ??:??:?? 0 myRegion->freqStart -> myRegion->freqEnd: 902.000000 -> 928.000000 (26.000000 MHz)
INFO  | ??:??:?? 0 numChannels: 104 x 250.000kHz
INFO  | ??:??:?? 0 channel_num: 20
INFO  | ??:??:?? 0 frequency: 906.875000
INFO  | ??:??:?? 0 Slot time: 77 msec
INFO  | ??:??:?? 0 Set radio: final power level=20
DEBUG | ??:??:?? 0 Current limit set to 100.000000
DEBUG | ??:??:?? 0 Current limit set result 0
INFO  | ??:??:?? 0 RF95 init result 0
INFO  | ??:??:?? 0 Frequency set to 906.875000
INFO  | ??:??:?? 0 Bandwidth set to 250.000000
INFO  | ??:??:?? 0 Power output set to 20
INFO  | ??:??:?? 0 RF95 init success
INFO  | ??:??:?? 0 Not using WIFI
DEBUG | ??:??:?? 0 LoRA bitrate = 118.394310 bytes / sec
INFO  | ??:??:?? 0 L[????M5?init, USB power=1
DEBUG | ??:??:?? 0 State: BOOT
[   978][D][esp32-hal-cpu.c:244] setCpuFrequencyMhz(): PLL: 320 / 4 = 80 Mhz, APB: 80000000 Hz
DEBUG | ??:??:?? 0 [Screen] Screen: Started...
DEBUG | ??:??:?? 1 [Screen] haveGlyphs=1
INFO  | ??:??:?? 1 [RangeTest] Range Test Module - Disabled
DEBUG | ??:??:?? 2 [Screen] haveGlyphs=1
DEBUG | ??:??:?? 3 [Screen] haveGlyphs=1
INFO  | ??:??:?? 4 [PowerFSM] Init the NimBLE bluetooth module
DEBUG | ??:??:?? 4 [Screen] haveGlyphs=1
DEBUG | ??:??:?? 5 [Screen] haveGlyphs=1
INFO  | ??:??:?? 6 [Screen] Done with boot screen
DEBUG | ??:??:?? 6 [Screen] Show standard frames
DEBUG | ??:??:?? 6 [Screen] Show 0 module frames
DEBUG | ??:??:?? 6 [Screen] Total frame count: 103
DEBUG | ??:??:?? 6 [Screen] Added modules.  numframes: 0
DEBUG | ??:??:?? 6 [Screen] Finished build frames. numframes: 2
INFO  | ??:??:?? 7 BLE authentication complete
INFO  | ??:??:?? 9 To Radio onwrite
DEBUG | ??:??:?? 9 New ToRadio packet
INFO  | ??:??:?? 9 Client wants config, nonce=38
DEBUG | ??:??:?? 9 Got 5 files in manifest
INFO  | ??:??:?? 9 Start API client config
INFO  | ??:??:?? 10 BLE disconnect
DEBUG | ??:??:?? 10 PhoneAPI::close()
INFO  | ??:??:?? 14 BLE authentication complete
INFO  | ??:??:?? 16 To Radio onwrite
DEBUG | ??:??:?? 16 New ToRadio packet
INFO  | ??:??:?? 16 Client wants config, nonce=39
DEBUG | ??:??:?? 16 Got 5 files in manifest
INFO  | ??:??:?? 16 Start API client config
DEBUG | ??:??:?? 16 FromRadio=STATE_SEND_MY_INFO
INFO  | ??:??:?? 16 getFromRadio=STATE_SEND_UIDATA
DEBUG | ??:??:?? 17 Send My NodeInfo
DEBUG | ??:??:?? 17 Send device metadata
ERROR | ??:??:?? 17 Panic: can't encode protobuf reason='unterminated string'
INFO  | ??:??:?? 30 [NodeInfo] Send our nodeinfo to mesh (wantReplies=1)
INFO  | ??:??:?? 30 [NodeInfo] Send owner !e3ca9dfc/Meshtastic 9dfc/9dfc
DEBUG | ??:??:?? 30 [NodeInfo] Initial packet id 1246751853
DEBUG | ??:??:?? 30 [NodeInfo] Partially randomized packet id 996202606
DEBUG | ??:??:?? 30 [NodeInfo] Update DB node 0xe3ca9dfc, rx_time=0
DEBUG | ??:??:?? 30 [NodeInfo] handleReceived(LOCAL) (id=0x3b60d86e fr=0xe3ca9dfc to=0xffffffff, WantAck=0, HopLim=3 Ch=0x0 Portnum=4 WANTRESP priority=10)
DEBUG | ??:??:?? 30 [NodeInfo] No modules interested in portnum=4, src=LOCAL
DEBUG | ??:??:?? 30 [NodeInfo] Add packet record (id=0x3b60d86e fr=0xe3ca9dfc to=0xffffffff, WantAck=0, HopLim=3 Ch=0x0 Portnum=4 WANTRESP priority=10)
DEBUG | ??:??:?? 30 [NodeInfo] Expand short PSK #1
DEBUG | ??:??:?? 30 [NodeInfo] Use AES128 key!
WARN  | ??:??:?? 30 [NodeInfo] send - lora tx disabled: Region unset
DEBUG | ??:??:?? 30 (Client not yet interested in packets)

[esev]

The version string looks too large

>>> len('2.5.22.9b46cb4ef086')
19

https://github.com/meshtastic/protobufs/blob/068646653e8375fc145988026ad242a3cf70f7ab/meshtastic/mesh.options#L72

*DeviceMetadata.firmware_version max_size:18

What is the output of this command? git rev-parse --short HEAD

[mhcerri]

@esev, that's a pretty good guess. I'm wondering if I can force the version string. It was generated automatically.

[esev]

I think the version string gets generated here:

firmware/bin/readprops.py

Line 33 in 9b46cb4

verObj["long"] = "{}.{}".format(verObj["short"], suffix)

And here:

firmware/bin/platformio-custom.py

Line 117 in 9b46cb4

"-DAPP_VERSION=" + verObj["long"],

[mhcerri]

Thank you! I will truncate it in both places to test it and I will update here once I have results!

[mhcerri]

Bingo!

I works! Truncating it just in firmware/bin/platformio-custom.py seems to be enough:

diff --git a/bin/platformio-custom.py b/bin/platformio-custom.py
index 09e8e6d839a3..7d22bdb15c06 100644
--- a/bin/platformio-custom.py
+++ b/bin/platformio-custom.py
@@ -114,7 +114,7 @@ for pref in userPrefs:
 
 # General options that are passed to the C and C++ compilers
 flags = [
-        "-DAPP_VERSION=" + verObj["long"],
+        "-DAPP_VERSION=" + verObj["long"][:17],
         "-DAPP_VERSION_SHORT=" + verObj["short"],
         "-DAPP_ENV=" + env.get("PIOENV"),
     ] + pref_flags

But truncating it to 18 wasn't enough. Maybe it keeps the '\n'? Not sure

[esev]

I think nanopb is looking for a null terminated C-style string. 17 bytes plus the null terminator at the end could make sense.

>>> len(b'2.5.22.9b46cb4ef0\0')
18

What you have looks good to me.

[mhcerri]

Makes sense.

Thanks a lot, @esev!