meshtastic / python

The Python CLI and API for talking to Meshtastic devices
https://meshtastic.org
339 stars 150 forks source link

Send text from python causes device to reboot #13

Closed mc-hamster closed 3 years ago

mc-hamster commented 3 years ago

Please - if you just have a question (i.e. not a bug report or a feature proposal), post in our forum instead.

Describe the bug Send text from python causes device to reboot and not reliably send text.

To Reproduce Steps to reproduce the behavior:

  1. Run the meshtastic python script with the following command:
  2. ./meshtastic --device /dev/cu.SLAB_USBtoUART --sendtext "asdf"

The text does get sent, but very infrequently.

Expected behavior I expect the device not to reboot and the string I'm sending to be sent.

Screenshots Video: http://www.casler.org/temp/IMG_0069.MOV

Device info:

Smartphone information (if relevant):

Additional context

??????????????????????????????????????????????????Emitting reboot packet for serial shell booted, wake cause 0 (boot count 1), reset_reason=reset I2C device found at address 0x34 axp192 PMU found I2C device found at address 0x3c ssd1306 display found done Meshtastic swver=0.9.5, hwver=1.0-US Setting random seed 1234553040 Total heap: 265492 Free heap: 238292 Total PSRAM: 4194252 Free PSRAM: 4194252 NVS: UsedEntries 91, FreeEntries 539, AllEntries 630 chip id detect 0x3 Detect CHIP :AXP192 OUTPUT Register 0x5f AXP192 Begin PASS DCDC1: ENABLE DCDC2: ENABLE LDO2: ENABLE LDO3: ENABLE DCDC3: ENABLE Exten: ENABLE

DCDC1: ENABLE DCDC2: ENABLE LDO2: ENABLE LDO3: ENABLE DCDC3: ENABLE Exten: ENABLE SRC REG:0xcf Charging enable is enable Charging target-voltage : 0x2 end when the charge current is lower than 10% of the set value Charge current : 1000.00 mA enable [0x40]val:0xdc enable [0x41]val:0xff enable [0x42]val:0x3b Turning on screen Read RTC time as 0 (cur millis 137) valid=0 Connected to UBLOX GPS successfully NOTE! Recording critical error 5, address=0 RadioConfig reset! Installing AES128 key! Initial packet id 1082405854, numPacketId 4294967295 Loading saved preferences Loaded saved preferences version 11 Installing AES256 key! NODENUM=0x336a8dc1, dbsize=1 Starting meshradio init... Set radio: name=oontz-2, config=2, ch=4, power=17 RF95 init result 0 [D][esp32-hal-cpu.c:189] setCpuFrequencyMhz(): PLL: 320 / 4 = 80 Mhz, APB: 80000000 Hz Battery 4138mV 100% sending owner !c44f336a8dc1/Cat/C Update DB node 0x336a8dc1, rx_time=0 old user !c44f336a8dc1/Cat/C updating changed=0 user !c44f336a8dc1/Cat/C Adding packet record (id=0x408433e1 Fr0xc1 To0xff, WantAck0, HopLim3 Payload:User) enqueuing for send (id=0x408433e1 Fr0xc1 To0xff, WantAck0, HopLim3 encrypted) txGood=0,rxGood=0,rxBad=0 Screen: Started... GPS fix type 0 Ignoring invalid GPS month=1, year=21268, unixtime=-1 New GPS pos lat=0.000000, lon=0.000000, alt=0, pdop=131.510000, heading=16675.930550, sats=204 Sending position to mesh Update DB node 0x336a8dc1, rx_time=0 Node status update: 1 online, 1 total showing standard frames Providing time to mesh 0 Adding packet record (id=0x408433e2 Fr0xc1 To0xff, WantAck0, HopLim3 Payload:Position) enqueuing for send (id=0x408433e2 Fr0xc1 To0xff, WantAck0, HopLim3 encrypted) txGood=0,rxGood=0,rxBad=0 Starting low level send (id=0x408433e1 Fr0xc1 To0xff, WantAck0, HopLim3 encrypted) showing standard frames Transition powerFSM transition=boot timeout, from=BOOT to=ON Setting bluetooth enable=1 Pre BT: 222456 heap size Starting bluetooth Completed sending (id=0x408433e1 Fr0xc1 To0xff, WantAck0, HopLim3 encrypted) BLE task running registered service 0x1800 with handle=1 registered service 0x1801 with handle=6 registered service 6ba1b218-15a8-461f-9fa8-5dcae273eafd with handle=10 registered service cb0b9a0b-a84c-4c0d-bdbb-442e3144ee30 with handle=18 BLE advertisting type=0, Private=0, Device Address: 39:c4:4f:33:6a:8d

Can not send yet, busyRx Can not send yet, busyRx Lora RX (id=0x9f2b9135 Fr0xc1 To0xff, WantAck0, HopLim0 encrypted rxSNR=10) Rx someone rebroadcasting for us (id=0x9f2b9135 Fr0xc1 To0xff, WantAck0, HopLim0 encrypted rxSNR=10) Adding packet record (id=0x9f2b9135 Fr0xc1 To0xff, WantAck0, HopLim0 encrypted rxSNR=10) FIXME not implementedFIXME-update-db Sniffing packet Delivering rx packet (id=0x9f2b9135 Fr0xc1 To0xff, WantAck0, HopLim0 Payload:Data WANTRESP rxSNR=10) Trigger powerFSM 3 Ignoring incoming time, because we have a GPS Forwarding to phone (id=0x9f2b9135 Fr0xc1 To0xff, WantAck0, HopLim0 Payload:Data WANTRESP rxSNR=10) Update DB node 0x336a8dc1, rx_time=0 Received text msg from=0x336a8dc1, id=-1624534731, msg=asdf Trigger powerFSM 5 Transition powerFSM transition=Received text, from=ON to=ON Node status update: 1 online, 1 total showing standard frames Sending network ping to 0x336a8dc1, with position=1, wantReplies=0 Update DB node 0x336a8dc1, rx_time=0 Node status update: 1 online, 1 total Providing time to mesh 0 Enqueuing internal message for the receive queue Adding packet record (id=0x408433e3 Fr0xc1 To0xc1, WantAck0, HopLim3 Payload:Position) FIXME not implementedFIXME-update-db Sniffing packet Delivering rx packet (id=0x408433e3 Fr0xc1 To0xc1, WantAck0, HopLim3 Payload:Position) Trigger powerFSM 3 Ignoring incoming time, because we have a GPS Forwarding to phone (id=0x408433e3 Fr0xc1 To0xc1, WantAck0, HopLim3 Payload:Position) Update DB node 0x336a8dc1, rx_time=0 Node status update: 1 online, 1 total Telling client we have new packets 2 Telling client we have new packets 2 No BLE notify Starting low level send (id=0x408433e2 Fr0xc1 To0xff, WantAck0, HopLim3 encrypted) Completed sending (id=0x408433e2 Fr0xc1 To0xff, WantAck0, HopLim3 encrypted) Lora RX (id=0x9f2b9135 Fr0xc1 To0xff, WantAck0, HopLim0 encrypted rxSNR=10.75) Rx someone rebroadcasting for us (id=0x9f2b9135 Fr0xc1 To0xff, WantAck0, HopLim0 encrypted rxSNR=10.75) Found existing packet record for fr=0x336a8dc1,to=0xffffffff,id=-1624534731 Ignoring incoming msg, because we've already seen it: fr=0x336a8dc1,to=0xffffffff,id=-1624534731,hop_limit=0 GPS fix type 0 Ignoring invalid GPS month=1, year=21268, unixtime=-1 Update DB node 0x336a8dc1, rx_time=0 Node status update: 1 online, 1 total Trigger powerFSM 9 Trigger powerFSM 11 Transition powerFSM transition=serial API, from=ON to=SERIAL Shutdown BT: 236288 heap size Connected to radio Sending text message asdf to ^all Received: {'from': 862621121, 'to': 4294967295, 'decoded': {'data': {'typ': 'CLEAR_TEXT', 'payload': 'YXNkZg==', 'text': 'asdf'}, 'wantResponse': True}, 'id': 2670432565, 'rxSnr': 10.0, 'fromId': '!c44f336a8dc1', 'toId': '^all'} Received: {'from': 862621121, 'to': 862621121, 'decoded': {'position': {'batteryLevel': 100}}, 'id': 1082405859, 'hopLimit': 3, 'fromId': '!c44f336a8dc1', 'toId': '!c44f336a8dc1'} jmcasler@Jms-Mac-mini bin % ./meshtastic --device /dev/cu.SLAB_USBtoUART --sendtext "asdf" Trigger powerFSM 9 Trigger powerFSM 11 Transition powerFSM transition=serial API, from=ON to=SERIAL Shutdown BT: 236840 heap size Connected to radio Sending text message asdf to ^all Trigger powerFSM 9 Trigger powerFSM 5 Trigger powerFSM 3 Received: {'from': 862621121, 'to': 862621121, 'decoded': {'successId': 2511103153}, 'id': 363619506, 'rxTime': 315964866, 'fromId': '!c44f336a8dc1', 'toId': '!c44f336a8dc1'}

geeksville commented 3 years ago

ooh interesting! that shouldn't happen (obviously). Can you rerun this with --debug --sendtext fish --device xxx --debug --seriallog logfile and attach the console output and logfile to this bug?

On my machine I get:

--sendtext fish --debug --seriallog logfile
INFO:root:Logging serial output to logfile
DEBUG:root:Connecting to /dev/ttyUSB0
DEBUG:root:Sending: want_config_id: 42

DEBUG:root:Received: {'myInfo': {'myNodeNum': 2883444536, 'hasGps': True, 'numChannels': 13, 'region': 'unset', 'hwModel': 'tbeam', 'firmwareVersion': 'unset', 'packetIdBits': 32, 'currentPacketId': 1399854153, 'nodeNumBits': 32, 'messageTimeoutMsec': 300000, 'minAppVersion': 172}}
DEBUG:root:Received: {'radio': {'preferences': {'positionBroadcastSecs': 900, 'sendOwnerInterval': 4, 'waitBluetoothSecs': 120, 'screenOnSecs': 300, 'phoneTimeoutSecs': 900, 'phoneSdsTimeoutSec': 7200, 'meshSdsTimeoutSecs': 7200, 'sdsSecs': 31536000, 'lsSecs': 3600}, 'channelSettings': {'modemConfig': 'Bw125Cr48Sf4096', 'psk': '1PG7OiApB1nwvP+rz05pvw==', 'name': 'Default'}}}
DEBUG:root:Received: {'nodeInfo': {'num': 2883444536, 'user': {'id': '!2462abdddf38', 'longName': 'Bob b', 'shortName': 'Bb', 'macaddr': 'JGKr3d84'}, 'position': {'batteryLevel': 100, 'time': 316024235}}}
DEBUG:root:Received: {'nodeInfo': {'num': 682754228, 'user': {'id': '!246f28b200b4', 'longName': 'Bob b', 'shortName': 'Bb', 'macaddr': 'JG8osgC0'}, 'position': {'batteryLevel': 100, 'time': 316024236}, 'snr': 12.5}}
DEBUG:root:Received: {'nodeInfo': {'num': 2441803616, 'user': {'id': '!5002918af760', 'longName': 'ryan', 'shortName': 'r', 'macaddr': 'UAKRivdg'}, 'position': {'batteryLevel': 61, 'time': 316497304}, 'snr': 10.0}}
DEBUG:root:Received: {'nodeInfo': {'num': 862631397, 'user': {'id': '!c44f336ab5e5', 'longName': 'Unknown b5e5', 'shortName': '?E5', 'macaddr': 'xE8zarXl'}, 'position': {'time': 1597965319}, 'snr': 13.25}}
DEBUG:root:Received: {'nodeInfo': {'num': 2441803548, 'user': {'id': '!5002918af71c', 'longName': 'Unknown f71c', 'shortName': '?1C', 'macaddr': 'UAKRivcc'}, 'position': {'batteryLevel': 47, 'time': 316494981}, 'snr': 9.5}}
DEBUG:root:Received: {'nodeInfo': {'num': 82599254, 'user': {'id': '!fd1004ec5d56', 'longName': 'Unknown 5d56', 'shortName': '?56', 'macaddr': '/RAE7F1W'}, 'position': {}, 'snr': 9.25}}
DEBUG:root:Received: {'nodeInfo': {'num': 2885173400, 'user': {'id': '!2462abf84098', 'longName': 'Unknown 4098', 'shortName': '?98', 'macaddr': 'JGKr+ECY'}, 'position': {'batteryLevel': 4, 'time': 315966200}, 'snr': 10.75}}
DEBUG:root:Received: {'configCompleteId': 42}
Connected to radio
Sending text message fish to ^all
DEBUG:root:Sending: packet {
  to: 4294967295
  decoded {
    data {
      typ: CLEAR_TEXT
      payload: "fish"
    }
    want_response: true
  }
  id: 3547337802
  want_ack: true
}

DEBUG:root:Received: {'packet': {'from': 2883444536, 'to': 2883444536, 'decoded': {'successId': 3547337802}, 'id': 1399854155, 'rxTime': 316024254}}
Received: {'from': 2883444536, 'to': 2883444536, 'decoded': {'successId': 3547337802}, 'id': 1399854155, 'rxTime': 316024254, 'fromId': '!2462abdddf38', 'toId': '!2462abdddf38'}
DEBUG:root:Closing serial stream
DEBUG:root:reader is exiting
kevinh@kevin-server:~/development/meshtastic/Meshtastic-python$ cat logfile 
Trigger powerFSM 9
Trigger powerFSM 9
Trigger powerFSM 5
Trigger powerFSM 3
mc-hamster commented 3 years ago

I can also cause the problem to occur if I ctrl+c from the meshtastic python script before getting a response back from any devices.

I'm running the firmware from my branch which was forked from master a few days ago. logfile.txt

geeksville commented 3 years ago

This issue has been mentioned on Meshtastic. There might be relevant details there:

https://meshtastic.discourse.group/t/module-crashing-with-send/1281/1

geeksville commented 3 years ago

Fixed by @mc-hamster https://github.com/meshtastic/Meshtastic-python/commit/e485af752beebb88eb2b80280acfacea246a9718

geeksville commented 3 years ago

released in 1.0.4 on pypi.