Hello,
We have implemented teltonika devices in our car/scooter sharing platform, but from time to time disconnects happen after sending a command. I believe that there is a bug or some strange race condition in the firmware.
- We're using FMB120, with DOUT1 and DOUT2 controlling ignition and alarm.
- Latest official firmware (Ver:03.25.05_00 GPS:AXN_5.10_3333 Hw:FMB120 Mod:33 IMEI:XXX Init:2019-8-27 8:54 Uptime:26264 MAC:001E42A36C26 SPC:1(0) AXL:0 OBD:0 BL:1.6 BT:4)
- DOUTs are configured as high priority on change and generate records when they are toggled.
- Movement is controlled by accelerometer. Start delay is 1 sec, stop is 10sec. High priority also.
- Connection is via TCP, our own backend. We have implemented Codec8, Codec8E and Codec12 in an node.js app.
- TCP ping is 30
- Records are generated every 30 seconds while moving and every 300 seconds while stopped.
I think I've managed to reproduce this in the lab, here is a log captured from the device:
[2019.08.27 10:39:50]-[NETWORK] data send to socket: 5, successfull! evt sending: enabled, VR socket: 0
>>> Last record sent to the server and confirmed.
[2019.08.27 10:39:55]-[MovDetect] state changed 0 -> 1 (movI:0, movD:0, spd:-1, delay:10)
[2019.08.27 10:39:55]-[MovDetect] Delaying movement 0 -> 1, cnt:1 tmo:3
[2019.08.27 10:39:56]-[MovDetect] Delaying movement 0 -> 1, cnt:2 tmo:3
[2019.08.27 10:39:57]-[REC.SEND.1] Mode: 0/Home on Stop. Time for next periodic data sending: 104 / 600
[2019.08.27 10:39:57]-[MovDetect] Delayed movement state changed:0 -> 1
[2019.08.27 10:39:57]-[REC.GEN] Eventual high priority record saved @ 0x000004F9
>>> High Priority record generated
[2019.08.27 10:39:57]-[REC.GEN] Record Content:
Timestamp: 1566902397000
(cut)
Record Size: 130 Bytes
[2019.08.27 10:39:57]-[REC.GEN] Priority High/Panic! Min Period:600
[2019.08.27 10:39:58]-[ModeChange] Home on Moving profile is updated and reloaded
>>> Move changed
[2019.08.27 10:40:00]-[NETWORK] [IND] received data from socket!
[2019.08.27 10:40:00]-[NETWORK] notification, socket id: 5 has data which must be read!
[2019.08.27 10:40:00]-[NETWORK] VR socket 0, real socket id: 5, attempt automatic data reading for application
[2019.08.27 10:40:00]-[NETWORK] attempting to read data from socked id (real): 5
[2019.08.27 10:40:00]-[NETWORK.PARSER] Parsing data from 0 socket, data len: 34
DUMP DATA START:
00 00 00 00 00 00 00 16 0C 01 05 00 00 00 0E 73 65 74 64 69 67 6F 75 74 20 30 30 0A 0D 01 00 00 2F D7
DUMP DATA END
[2019.08.27 10:40:00]-[NETWORK.PARSER] GPRS CMD Detected!
[2019.08.27 10:40:00]-[GPRS.CMD] CID: 12, NOD: 1, CMD: 5, data len: 14, CRC: 2FD7
[2019.08.27 10:40:00]-[SMS.CMD] DOUT1 NewState:0 Tmo:0 Speed:-1
[2019.08.27 10:40:00]-[IO.APP] Saving DOUT1 State:[0] to Flash
>>> Command received and executed
[2019.08.27 10:40:00]-[REC.GEN] Eventual high priority record saved @ 0x000004FA
[2019.08.27 10:40:00]-[REC.GEN] Record Content:
Timestamp: 1566902400000
Priority : 2
(cut)
Record Size: 130 Bytes
[2019.08.27 10:40:00]-[REC.GEN] Priority High/Panic! Min Period:30
[2019.08.27 10:40:00]-[SMS.CMD] DOUT2 NewState:0 Tmo:0 Speed:-1
[2019.08.27 10:40:00]-[SMS.CMD] DOUT3 NewState:-1 Tmo:0 Speed:-1
[2019.08.27 10:40:00]-[GPRS.CMD] cmd response: DOUT1:0 Timeout:INFINITY DOUT2:0 Timeout:INFINITY
[2019.08.27 10:40:00]-[NETWORK] attempting to send data by VR socked id: 5, data len: 70
[2019.08.27 10:40:00]-[NETWORK] [SEND.DATA.0151] Waiting for socket send result, waiting: 10 sec
[2019.08.27 10:40:00]-[NETWORK] data send to socket: 5, successfull! evt sending: enabled, VR socket: 0
>>> At this point nothing was sent to the server
[2019.08.27 10:40:01]-[REC.SEND.1] WARNING @ 735:No server response to sent records [1], rec sending canceled
>>> Here the device decides that there is no response in time for a record it didn't send and decided to close the socket.
[2019.08.27 10:40:01]-[REC.SEND.1] [CHANGE.STATE.0736] Server: 0, send records => finish
[2019.08.27 10:40:02]-[REC.SEND.1] finish
[2019.08.27 10:40:02]-[NETWORK] attempting to close socked by id: 5
[2019.08.27 10:40:02]-[NETWORK] [SOCKET.CLOSE.0794] Waiting for close result, waiting: 10 sec
[2019.08.27 10:40:02]-[NETWORK] socket closing by id: 5 success! evt sending: enabled
[2019.08.27 10:40:02]-[REC.SEND.1] Caller: 1210, queueing recsend1 task job type: 2/close link
[2019.08.27 10:40:02]-[NETWORK] VR socket 0 closed! Real:5
[2019.08.27 10:40:02]-[REC.SEND.1] socket closing result: 1
[2019.08.27 10:40:02]-[REC.SEND.1] [CHANGE.STATE.0801] Server: 0, finish => finished
[2019.08.27 10:40:02]-[REC.SEND.1] finished
[2019.08.27 10:40:02]-[REC.SEND.1] [CHANGE.STATE.0167] Server: 0, finished => finish
[2019.08.27 10:40:02]-[REC.SEND.1] finish
[2019.08.27 10:40:02]-[REC.SEND.1] [CHANGE.STATE.0801] Server: 0, finish => finished
[2019.08.27 10:40:02]-[REC.SEND.1] finished
After some time device reconnected and sent the records.
I think a similar issue was described on this topic
(had to remove formatting because of max character limitation, complete log is available here)