meshtastic / python

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

cli command sendtext causes device restart #5

Closed z0ne0 closed 4 years ago

z0ne0 commented 4 years ago

meshtastic --device /dev/cu.SLAB_USBtoUART --sendtext hello

By using above command on macbook (10.15.6 Catalina), sending text message from Device A to be able to test onReceive event on iOS client connected to Device B. Unfortunately, Device A immediately restarts by running this command. 1- How can I resolve this if it's already known issue? 2- Could you please share how can I debug such situations on device?

geeksville commented 4 years ago

hmm works on my machine

kevinh@kevin-server:~/development/meshtastic/Meshtastic-python$ bin/run.sh --device /dev/ttyUSB0 --sendtext fish
Connected to radio
Sending text message fish to ^all
Received: {'from': 682754228, 'to': 682754228, 'decoded': {'successId': 244451454}, 'id': 244451455, 'fromId': '!246f28b200b4', 'toId': '!246f28b200b4'}

what version of the device code?

re how to debug:

Unfortunately (though by design), whenever we switch to using the protocol over the serial link, we turn off serial debug messages on the device. To debug this you'll need to comment out the following line in src/SerialConsole.cpp

void SerialConsole::handleToRadio(const uint8_t *buf, size_t len)
{
    // Turn off debug serial printing once the API is activated, because other threads could print and corrupt packets
    setDestination(&noopPrint);  COMMENT OUT THIS LINE

You will also want to "pip3 install --upgrade meshtastic" to get a fix I just added so you can see debug output while --settext is running. At that point you should see (note the special options I passed into the meshtastic command):

Meshtastic-python$ bin/run.sh --device /dev/ttyUSB0 --sendtext fish --debug --seriallog stdout
rm: cannot remove 'log_*': No such file or directory
DEBUG:root:Connecting to /dev/ttyUSB0
DEBUG:root:Sending: want_config_id: 42

Trigger powerFSM 9
Trigger powerFSM 11
Transition powerFSM transition=serial API, from=ON to=SERIAL
Setting bluetooth enable=0
advertise complete; reason=29error enabling advertisement; rc=30
Done shutting down bluetooth
Shutdown BT: 236576 heap size
Client wants config, nonce=42
Reset nodeinfo read pointer
getFromRadio, state=2
encoding toPhone packet to phone variant=3, 50 bytes
DEBUG:root:Received: {'myInfo': {'myNodeNum': 682754228, 'hasGps': True, 'numChannels': 13, 'region': 'unset', 'hwModel': 'tbeam', 'firmwareVersion': 'unset', 'packetIdBits': 32, 'currentPacketId': 1212341509, 'nodeNumBits': 32, 'messageTimeoutMsec': 300000, 'minAppVersion': 172}}
getFromRadio, state=3
encoding toPhone packet to phone variant=6, 64 bytes
DEBUG:root:Received: {'radio': {'preferences': {'positionBroadcastSecs': 900, 'sendOwnerInterval': 4, 'waitBluetoothSecs': 120, 'screenOnSecs': 300, 'phoneTimeoutSecs': 900, 'phoneSdsTimeoutSec': 7200, 'meshSdsTimeoutSecs': 7200, 'sdsSecs': 31536000, 'lsSecs': 3600}, 'channelSettings': {'txPower': 23, 'modemConfig': 'Bw125Cr48Sf4096', 'psk': '1PG7OiApB1nwvP+rz05pvw==', 'name': 'Default'}}}
getFromRadio, state=4
Sending nodeinfo: num=0x28b200b4, lastseen=1595656348, id=!246f28b200b4, name=Unknown 00b4
encoding toPhone packet to phone variant=4, 75 bytes
DEBUG:root:Received: {'nodeInfo': {'num': 682754228, 'user': {'id': '!246f28b200b4', 'longName': 'Unknown 00b4', 'shortName': '?B4', 'macaddr': 'JG8osgC0'}, 'position': {'altitude': 126, 'batteryLevel': 100, 'latitudeI': 375209838, 'longitudeI': -1223090811, 'time': 1595656348}}}
getFromRadio, state=4
Sending nodeinfo: num=0xabdddf38, lastseen=1595656364, id=!2462abdddf38, name=Bob b
encoding toPhone packet to phone variant=4, 73 bytes
DEBUG:root:Received: {'nodeInfo': {'num': 2883444536, 'user': {'id': '!2462abdddf38', 'longName': 'Bob b', 'shortName': 'Bb', 'macaddr': 'JGKr3d84'}, 'position': {'altitude': 141, 'batteryLevel': 58, 'latitudeI': 375211401, 'longitudeI': -1223090693, 'time': 1595656364}, 'snr': 10.5}}
getFromRadio, state=4
Sending nodeinfo: num=0xabf84098, lastseen=1594239571, id=!2462abf84098, name=bx n
encoding toPhone packet to phone variant=4, 71 bytes
DEBUG:root:Received: {'nodeInfo': {'num': 2885173400, 'user': {'id': '!2462abf84098', 'longName': 'bx n', 'shortName': 'bn', 'macaddr': 'JGKr+ECY'}, 'position': {'altitude': 127, 'batteryLevel': 100, 'latitudeI': 375209756, 'longitudeI': -1223090402, 'time': 1594239571}, 'snr': 9.25}}
getFromRadio, state=4
Sending nodeinfo: num=0x28b5367c, lastseen=1595203167, id=!246f28b5367c, name=Unknown 367c
encoding toPhone packet to phone variant=4, 64 bytes
DEBUG:root:Received: {'nodeInfo': {'num': 682964604, 'user': {'id': '!246f28b5367c', 'longName': 'Unknown 367c', 'shortName': '?7C', 'macaddr': 'JG8otTZ8'}, 'position': {'time': 1595203167}, 'snr': 9.25}}
getFromRadio, state=4
Done sending nodeinfos
getFromRadio, state=5
encoding toPhone packet to phone variant=8, 2 bytes
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
  }
  want_ack: true
}

Trigger powerFSM 9
PACKET FROM PHONE (id=0x00000000 Fr0x00 To0xff, WantAck1, HopLim0 Payload:Data WANTRESP)
Ignoring incoming packet - not a position
Update DB node 0x28b200b4, rx_time=0
Received text msg from=0x28b200b4, id=1212341510, msg=fish
Trigger powerFSM 5
Node status update: 4 online, 4 total
showing standard frames
Adding packet record (id=0x4842dd06 Fr0xb4 To0xff, WantAck1, HopLim1 Payload:Data WANTRESP)
enqueuing for send (id=0x4842dd06 Fr0xb4 To0xff, WantAck0, HopLim1 encrypted)
txGood=1,rxGood=0,rxBad=0
Can not send yet, busyRx
Can not send yet, busyRx
GPS fix type 0
Setting RTC 1596399207 secs
Read RTC time as 1596399207 (cur millis 12024) valid=1
New GPS pos lat=37.520957, lon=-122.309017, alt=133, pdop=99.990000, heading=15.242270, sats=0
Can not send yet, busyRx
Lora RX (id=0x4842dd05 Fr0xb4 To0xff, WantAck0, HopLim2 encrypted)
Rx someone rebroadcasting for us (id=0x4842dd05 Fr0xb4 To0xff, WantAck0, HopLim2 encrypted)
Found existing packet record for fr=0x28b200b4,to=0xffffffff,id=1212341509
Ignoring incoming msg, because we've already seen it: fr=0x28b200b4,to=0xffffffff,id=1212341509,hop_limit=2
Can not send yet, busyRx
Can not send yet, busyRx
Can not send yet, busyRx
Can not send yet, busyRx
Lora RX (id=0x19240fe3 Fr0x38 To0xb4, WantAck0, HopLim3 encrypted)
Adding packet record (id=0x19240fe3 Fr0x38 To0xb4, WantAck0, HopLim3 encrypted)
FIXME not implementedFIXME-update-db Sniffing packet
Delivering rx packet (id=0x19240fe3 Fr0x38 To0xb4, WantAck0, HopLim3 Payload:User rxtime=1596399212)
Trigger powerFSM 3
Ignoring incoming time, because we have a GPS
Forwarding to phone (id=0x19240fe3 Fr0x38 To0xb4, WantAck0, HopLim3 Payload:User rxtime=1596399212)
Update DB node 0xabdddf38, rx_time=1596399212
old user !2462abdddf38/Bob b/Bb
updating changed=0 user !2462abdddf38/Bob b/Bb
Telling client we have new packets 1
Telling client we have new packets 1
No BLE notify
getFromRadio, state=6
encoding toPhone packet to phone variant=2, 70 bytes
DEBUG:root:Received: {'packet': {'from': 2883444536, 'to': 682754228, 'decoded': {'user': {'id': '!2462abdddf38', 'longName': 'Bob b', 'shortName': 'Bb', 'macaddr': 'JGKr3d84'}}, 'id': 421793763, 'rxSnr': 11.0, 'rxTime': 1596399212, 'hopLimit': 3}}
Received: {'from': 2883444536, 'to': 682754228, 'decoded': {'user': {'id': '!2462abdddf38', 'longName': 'Bob b', 'shortName': 'Bb', 'macaddr': 'JGKr3d84'}}, 'id': 421793763, 'rxSnr': 11.0, 'rxTime': 1596399212, 'hopLimit': 3, 'fromId': '!2462abdddf38', 'toId': '!246f28b200b4'}
DEBUG:root:Closing serial stream
DEBUG:root:reader is exiting
geeksville commented 4 years ago

would you mind trying this command and see what the logoutput is? (alas - I'm unable to repro this failure on my machine)

z0ne0 commented 4 years ago

While opening the issue, device fw version was 0.9.1, recently tried with device fw 0.7.9 as well but device restarted here too.

  1. Device fw 0.7.9, with the previous python commit 2800366319fd3bae7e28ca70236cbde9db48f532
$ meshtastic --device /dev/cu.SLAB_USBtoUART --sendtext hello4
Trigger powerFSM 9
Trigger powerFSM 11
Transition powerFSM transition=serial API, from=ON to=SERIAL
Shutdown BT: 210604 heap size
Connected to radio
Sending text message hello4 to ^all
Trigger powerFSM 9
Trigger powerFSM 5
Trigger powerFSM 3
Received: {'from': 3290844660, 'to': 3290844660, 'decoded': {'failId': 324416643}, 'id': 324416644, 'fromId': '!fcf5c4264df4', 'toId': '!fcf5c4264df4'}

-- Please take following for firmware-heltec-EU865-0.9.1.bin release and the recent python commit 9da57e2d12ee440bd291d85f2ae64521529444ec

I will try to send another update in addition to this tomorrow by commenting out the line in device code and upload it to device (never did it before, will check it out). For now, sharing current findings and test results, hope it means sth. Results below are for two scenarios since it behaves differently for device restart moment.

  1. Only one device connected (no other device to receive a message)

DEBUG:root:Received: {'myInfo': {'myNodeNum': 3290844660, 'numChannels': 10, 'region': '1.0-EU865', 'hwModel': 'heltec', 'firmwareVersion': '0.9.1', 'packetIdBits': 32, 'currentPacketId': 1934395018, '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': {'txPower': 23, 'modemConfig': 'Bw125Cr48Sf4096', 'psk': '1PG7OiApB1nwvP+rz05pvw==', 'name': 'Default'}}} DEBUG:root:Received: {'nodeInfo': {'num': 3290844660, 'user': {'id': '!fcf5c4264df4', 'longName': 'Unknown 4df4', 'shortName': '?F4', 'macaddr': '/PXEJk30'}}} DEBUG:root:Node without position DEBUG:root:Received: {'configCompleteId': 42} Connected to radio Sending text message hello11 to ^all DEBUG:root:Sending: packet { to: 4294967295 decoded { data { typ: CLEAR_TEXT payload: "hello11" } want_response: true } want_ack: true }

DEBUG:root:Received: {'packet': {'from': 3290844660, 'to': 3290844660, 'decoded': {'failId': 1934395019}, 'id': 1934395020}} Received: {'from': 3290844660, 'to': 3290844660, 'decoded': {'failId': 1934395019}, 'id': 1934395020, 'fromId': '!fcf5c4264df4', 'toId': '!fcf5c4264df4'} DEBUG:root:Closing serial stream DEBUG:root:reader is exiting


2. 2 devices connected and **discovered** each other

* Device **immediately** restarts

$ bin/run.sh --device /dev/cu.SLABUSBtoUART --sendtext hello22 --debug --seriallog stdout rm: log*: No such file or directory DEBUG:root:Not logging serial output DEBUG:root:Connecting to /dev/cu.SLAB_USBtoUART DEBUG:root:Sending: want_config_id: 42

DEBUG:root:Received: {'myInfo': {'myNodeNum': 3290844660, 'numChannels': 10, 'region': '1.0-EU865', 'hwModel': 'heltec', 'firmwareVersion': '0.9.1', 'packetIdBits': 32, 'currentPacketId': 172665653, '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': {'txPower': 23, 'modemConfig': 'Bw125Cr48Sf4096', 'psk': '1PG7OiApB1nwvP+rz05pvw==', 'name': 'Default'}}} DEBUG:root:Received: {'nodeInfo': {'num': 3290844660, 'user': {'id': '!fcf5c4264df4', 'longName': 'Unknown 4df4', 'shortName': '?F4', 'macaddr': '/PXEJk30'}}} DEBUG:root:Node without position DEBUG:root:Received: {'nodeInfo': {'num': 680981132, 'user': {'id': '!246f2896f28c', 'longName': 'Unknown f28c', 'shortName': '?8C', 'macaddr': 'JG8olvKM'}, 'snr': 10.0}} DEBUG:root:Node without position DEBUG:root:Received: {'configCompleteId': 42} Connected to radio Sending text message hello22 to ^all DEBUG:root:Sending: packet { to: 4294967295 decoded { data { typ: CLEAR_TEXT payload: "hello22" } want_response: true } want_ack: true }

DEBUG:root:Received: {'packet': {'from': 680981132, 'to': 4294967295, 'decoded': {'user': {'id': '!246f2896f28c', 'longName': 'Unknown f28c', 'shortName': '?8C', 'macaddr': 'JG8olvKM'}}, 'id': 485721498, 'rxSnr': 10.75, 'hopLimit': 3}} Received: {'from': 680981132, 'to': 4294967295, 'decoded': {'user': {'id': '!246f2896f28c', 'longName': 'Unknown f28c', 'shortName': '?8C', 'macaddr': 'JG8olvKM'}}, 'id': 485721498, 'rxSnr': 10.75, 'hopLimit': 3, 'fromId': '!246f2896f28c', 'toId': '^all'} DEBUG:root:Received: {'packet': {'from': 680981132, 'to': 3290844660, 'decoded': {'user': {'id': '!246f2896f28c', 'longName': 'Unknown f28c', 'shortName': '?8C', 'macaddr': 'JG8olvKM'}, 'wantResponse': True}, 'id': 485721499, 'rxSnr': 12.0, 'hopLimit': 3}} Received: {'from': 680981132, 'to': 3290844660, 'decoded': {'user': {'id': '!246f2896f28c', 'longName': 'Unknown f28c', 'shortName': '?8C', 'macaddr': 'JG8olvKM'}, 'wantResponse': True}, 'id': 485721499, 'rxSnr': 12.0, 'hopLimit': 3, 'fromId': '!246f2896f28c', 'toId': '!fcf5c4264df4'} DEBUG:root:Closing serial stream DEBUG:root:reader is exiting

geeksville commented 4 years ago

ok - super great info. I'll make a fix related to your through report.

geeksville commented 4 years ago

@z0ne0 actually I just read more carefully. alas, the missing key info I think is:

setDestination(&noopPrint); COMMENT OUT THIS LINE

can you try this and send me the logs? Because alas - I still can't repro it here. (If you aren't able to build the device code, just let me know and I can build it here and add a bin for you?)

Thank you for reporting this and helping track it down.

geeksville commented 4 years ago

alas - I can't repro this. Closing for now to keep the queues tidy. @z0ne0 if it is still happening for you can you reopen?