Time Sync from the phone fails

EDsteve commented 4 months ago

@LIFsCode @OOHehir @josephx86 Might that be a app issue? Not sure.

Sorry for another issue :/ But sometimes i get recordings from 1970 because they don't get the time from the phone. So i was hunting the time-sync issue and was "successful" :)

How it happens:

Running firmware version: Release/V1.0-16-gd1e8350-dirty (But this issue also happened with commits from weeks before)

Boot the ELOC
Connect with the app
Disconnect before the time sync happens
Connect again and do a few fast refreshs (swipe down in the app = reconnect to ELOC = refresh status)

That's what i did. But maybe some random quick reconnects will do the job too.

Result

This should give you some BT errors and sometimes also the timesync problem. Starts with this: E (93606) BtCmds: Parsing time config failed with IncompleteInput And then this, which i then often also get after restarting the ELOC: [E][BluetoothSerial.cpp:342] esp_spp_cb(): RX Full! Discarding 20 bytes E (51332) BluetoothServer: Invalid Command gesetTime, Received gesetTime

The [E][BluetoothSerial.cpp error does not appear in the ELOC log file. Not sure why. That's why i have uploaded two logs:

This is the log file from the ELOC (problem starts @ line 4482): Time_Sync_Failed.log And this a logfile from VScode including the [E][BluetoothSerial.cpp Errors (Not the same time as ELOC log): Time Sync fail with BT_Serial_Error.txt

Running with this Configuration:

{
  "device": {
    "fileHeader": "34",
    "locationCode": "UNKNOWN",
    "locationAccuracy": 100,
    "nodeName": "ELOC_344"
  },
  "config": {
    "secondsPerFile": 3600,
    "cpuMaxFrequencyMHZ": 80,
    "cpuMinFrequencyMHZ": 10,
    "cpuEnableLightSleep": true,
    "bluetoothEnableAtStart": true,
    "bluetoothEnableOnTapping": true,
    "bluetoothEnableDuringRecord": true,
    "bluetoothOffTimeoutSeconds": 120,
    "logConfig": {
      "logToSdCard": true,
      "filename": "/sdcard/log/eloc.log",
      "maxFiles": 10,
      "maxFileSize": 52100000
    },
    "intruderCfg": {
      "enable": false,
      "threshold": 5,
      "windowsMs": 2000
    },
    "battery": {
      "updateIntervalMs": 600000,
      "avgSamples": 10,
      "avgIntervalMs": 0,
      "noBatteryMode": false
    }
  },
  "mic": {
    "MicType": "ns",
    "MicBitShift": 11,
    "MicSampleRate": 16000,
    "MicUseAPLL": true,
    "MicUseTimingFix": true,
    "MicChannel": "Left"
  }

In case it helps i have a collection of BT errors which i accumulated over the last weeks. Every error belongs to it's own log which you can find here: BT errors collection.txt

E (35985) BT_BTC: btc_spp_cb_handler unable to find RFCOMM slot!, handle:129

E (177458) BluetoothServer: Invalid Command getStatggetStatusgetStatus, Received getStatggetStatusgetStatus

E (44463) BT_HCI: command_timed_out hci layer timeout waiting for response to a command. opcode: 0x40f

E (40746) BT_BTC: btc_spp_write unable to find RFCOMM slot!

[ 40864][E][BluetoothSerial.cpp:327] esp_spp_cb(): ESP_SPP_WRITE_EVT failed!, status:7

josephx86 commented 4 months ago

Getting the date set to 1970 means some recordings are being started before the time sync has completed. The app runs the time sync command in the background and I would guess if recording is started before syncing is completed, it makes sense the date/time would be 1970. I will re-implement the "handshake" between phone and board to block further commands being sent to the board until the time sync is completed successfully. In the app this will mean seeing a connecting progressbar until the time sync command succeeds. This will likely be less than 2 seconds.

LIFsCode commented 4 months ago

@EDsteve Great find.

Maybe too many commands or too long commands are sent at once. There is a limitation in the Bluetooth stack which limits the Rx buffer size.

This may also be affected by the total CPU load when the Rx queue is not emptied fast enough.

The invalid command is either caused by this and missing bytes or by missing /r/n termination

EDsteve commented 4 months ago

@josephx86 @LIFsCode

I would guess if recording is started before syncing is completed,

I don't think it is possible to start recording before a time sync has happened (or at least i never observed that). Only when a time sync fails due to BT errors, a recording from 1970 can happen. And even that suprises me because i thought the build time is used if there is no time from the phone or is there something i am missing? @LIFsCode

The connection progress bar is a good idea. The problem is, that it takes 16 second after a BT connection for the time-sync to happen. And that is a too long time to wait. I think the reason for that is because it seems the app asks 16 times getStatus every second after a BT connection. Only after that the time sync happens. Is that correct? @josephx86

When i send the command getStatus. I see this line in the log: I (18741) Battery: Calibrate voltage: read 3.301V, offset 0.000, scale 1.000000, result 3.301V I (18753) COMMANDS: WavWriterMode = disabled(0), AI = OFF I (18761) SDC: SD card free space: 118.825714 GB I (18768) SDC: SD card free space: 124597792 KiB

So i am assuming that the app sends the command getStatus 16 times after a BT connection.

This is the log after a BT connection till the time sync (I removed the task-table from the log to make it more easy to read):

I (10522) BluetoothServer: SerialBT is ready ------------------------------------------------------ 
I (10602) main: Battery: Voltage: 3.319V, 83% SoC, Temp 31 °C
I (10610) main: Heap: Min=94652, free=96040 (49%), largestFreeBlock=90112, fragmentation=7%
I (10620) main: PSRAM Heap: Min=4164071, free=4165187 (1%), largestFreeBlock=4128768, fragmentation=1%
I (10984) gpio: GPIO[13]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
W (17092) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (17109) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 8000
W (18020) BT_APPL: new conn_srvc id:26, app_id:255
I (18308) gpio: GPIO[13]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (18741) Battery: Calibrate voltage: read 3.301V, offset 0.000, scale 1.000000, result 3.301V
I (18753) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (18761) SDC: SD card free space: 118.825714 GB
I (18768) SDC: SD card free space: 124597792 KiB
I (19684) Battery: Calibrate voltage: read 3.301V, offset 0.000, scale 1.000000, result 3.301V
I (19709) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (19718) SDC: SD card free space: 118.825714 GB
I (19724) SDC: SD card free space: 124597792 KiB
I (20616) Battery: Calibrate voltage: read 3.301V, offset 0.000, scale 1.000000, result 3.301V
I (20625) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (20648) SDC: SD card free space: 118.825714 GB
I (20654) SDC: SD card free space: 124597792 KiB
I (20721) main: Battery: Voltage: 3.301V, 70% SoC, Temp 31 °C
I (20729) main: Heap: Min=85716, free=88276 (53%), largestFreeBlock=81920, fragmentation=8%
I (20741) main: PSRAM Heap: Min=4164071, free=4165187 (1%), largestFreeBlock=4128768, fragmentation=1%
I (21565) Battery: Calibrate voltage: read 3.300V, offset 0.000, scale 1.000000, result 3.300V
I (21572) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (21579) SDC: SD card free space: 118.825714 GB
I (21583) SDC: SD card free space: 124597792 KiB
I (22483) Battery: Calibrate voltage: read 3.300V, offset 0.000, scale 1.000000, result 3.300V
I (22516) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (22524) SDC: SD card free space: 118.825714 GB
I (22530) SDC: SD card free space: 124597792 KiB
W (23186) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 798, status 0x0
I (23433) Battery: Calibrate voltage: read 3.322V, offset 0.000, scale 1.000000, result 3.322V
I (23452) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (23458) SDC: SD card free space: 118.825714 GB
I (23462) SDC: SD card free space: 124597792 KiB
W (23471) BT_HCI: hci cmd send: unsniff: hdl 0x80
I (24288) Battery: Calibrate voltage: read 3.322V, offset 0.000, scale 1.000000, result 3.322V
I (24300) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (24305) SDC: SD card free space: 118.825714 GB
I (24309) SDC: SD card free space: 124597792 KiB
W (24665) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
I (25127) Battery: Calibrate voltage: read 3.301V, offset 0.000, scale 1.000000, result 3.301V
I (25146) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (25154) SDC: SD card free space: 118.825714 GB
I (25161) SDC: SD card free space: 124597792 KiB
I (26055) Battery: Calibrate voltage: read 3.300V, offset 0.000, scale 1.000000, result 3.300V
I (26067) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (26085) SDC: SD card free space: 118.825714 GB
I (26092) SDC: SD card free space: 124597792 KiB
I (26971) Battery: Calibrate voltage: read 3.300V, offset 0.000, scale 1.000000, result 3.300V
I (26981) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (26985) SDC: SD card free space: 118.825714 GB
I (26997) SDC: SD card free space: 124597792 KiB
I (27906) Battery: Calibrate voltage: read 3.300V, offset 0.000, scale 1.000000, result 3.300V
I (27918) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (27925) SDC: SD card free space: 118.825714 GB
I (27932) SDC: SD card free space: 124597792 KiB
I (28869) Battery: Calibrate voltage: read 3.300V, offset 0.000, scale 1.000000, result 3.300V
I (28881) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (28889) SDC: SD card free space: 118.825714 GB
I (28895) SDC: SD card free space: 124597792 KiB
W (29721) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 798, status 0x0
I (29853) Battery: Calibrate voltage: read 3.320V, offset 0.000, scale 1.000000, result 3.320V
I (29860) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (29865) SDC: SD card free space: 118.825714 GB
I (29869) SDC: SD card free space: 124597792 KiB
W (29878) BT_HCI: hci cmd send: unsniff: hdl 0x80
I (30688) Battery: Calibrate voltage: read 3.318V, offset 0.000, scale 1.000000, result 3.318V
I (30695) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (30700) SDC: SD card free space: 118.825714 GB
I (30704) SDC: SD card free space: 124597792 KiB
W (30773) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
I (30800) main: Battery: Voltage: 3.318V, 82% SoC, Temp 31 °C
I (30809) main: Heap: Min=83624, free=84968 (55%), largestFreeBlock=77824, fragmentation=9%
I (30820) main: PSRAM Heap: Min=4164071, free=4165187 (1%), largestFreeBlock=4128768, fragmentation=1%
I (31574) Battery: Calibrate voltage: read 3.300V, offset 0.000, scale 1.000000, result 3.300V
I (31585) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (31604) SDC: SD card free space: 118.825714 GB
I (31611) SDC: SD card free space: 124597792 KiB
I (32546) Battery: Calibrate voltage: read 3.300V, offset 0.000, scale 1.000000, result 3.300V
I (32566) COMMANDS: WavWriterMode = disabled(0), AI = OFF
I (32574) SDC: SD card free space: 118.825714 GB
I (32587) SDC: SD card free space: 124597792 KiB
I (34980) BtCmds: updating time with {"seconds":1709530008, "ms" : -564, "timezone" : 7}
I (34990) BtCmds: timestamp in from type ? Time Zone: 7 sec: 1709530008 millisec: -564
I (34998) BtCmds: new timestamp from new sys time (local time) 1709555207436
I (35004) BtCmds: new timestamp from timeobJect (local time) 158223634
I (35019) BtCmds: new time set to (local time) Mon, Mar 04 2024 12:26:47
W (35811) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 798, status 0x0
W (37456) BT_HCI: hcif ssr evt: st 0x0, hdl 0x80, tx_lat 798 rx_lat 798

I (40943) main: Battery: Voltage: 3.300V, 70% SoC, Temp 32 °C

josephx86 commented 4 months ago

Sending getStatus 16 times in a short span of time is definitely inefficient. The app requests info from the board depending on UI events, so I will refactor the code and reduce the number of requests.

Another thing, that I was hoping to bring up later after I had written a patch with the feature is can we add a field in the response from a board that will have an ID that matches an ID provided as an integer parameter in the request? This will help improve 2 issues. The first is that the app can better keep track of which requests have been completed. Second, for uploading data from the board, the app needs to match a getStatus response with a getConfig response. So far, there is no reliable way to match the 2 responses. Some times it is necessary to call getStatus twice within 10 seconds. If some requests are indeed getting dropped, the files to be uploaded to the database might have incorrect state information.

LIFsCode commented 4 months ago

@josephx86 currently the interface was intended to serve only a single command at a time, i.e. all commands are responded and the next command is not expected to be issued before the first commands response is received.

If that's an issue and the app requires multiple commands at once in the flight, this can be easily changed from a device perspective, but then it definitely requires a command ID for command and responses to match. This could be easily identified via the cmdVersion sent during the initial connection message.

@josephx86 do you require this? Should I make a proposal for interface version 2?

josephx86 commented 4 months ago

I did not understand the part about using the cmdVersion, isn't that attribute always a constant value?

josephx86 commented 4 months ago

do you require this? Should I make a proposal for interface version 2?

I need a way to match the response of getStatus and getConfig at a given time. This is because the information in from both command responses will be combined into a single database record. So I can either make 2 separate requests for each command, but the app will keep track of the IDs so that it knows which getStatus response and getConfig response should be matched. Or alternatively, we could introduce a new command, like say "getInfo" for example, that will return a combination of information from getStatus and getConfig.

I do not yet fully understand the intricacies of the firmware code but I would imagine it would be easier for the board to read the ID parameter supplied with a command, and then include the same ID back in the response. Something like:

getStatus#id=56\n

and the respnse would be something like:

{ "id": 56, "ecode" : 0, "cmd" : "getStatus", "payload" : { . . . }<EOT>

LIFsCode commented 4 months ago

@josephx86

Sorry this was a bit confusing by me. What I meant is that we increment the cmdVersion:

cmdVersion 1: --> no ID field in responses
cmdVersion 2: --> ID field in all responses

I implmented it in b8cb4b6 the folllowing way:

no id= field in command --> id in response will be -1
id in the command --> id in the response will match

Is that fine for you? if yes I'll update it in the wiki

A few examples

{"device" : "ELOC 3.0", "cmdVersion" : 2}

setRecordMode#id=42#mode=recordOn_DetectOff ==>

{"id" : 42, "ecode" : 0, "error" : "ESP_OK", "cmd" : "setRecordMode", "payload" : {
  "recordingState": {
    "val": 2,
    "state": "recordOn_detectOff"
  }
}}

getStatus#id=666 ==>

{"id" : 666, "ecode" : 0, "error" : "ESP_OK", "cmd" : "getStatus", "payload" : {
  "battery": {
    "type": "no Battery",
    "state": "Full",
    "SoC[%]": 78.9,
    "voltage[V]": 3.31
  },
  "session": {
    "identifier": "",
    "recordingState": {
      "val": 1,
      "state": "recordOff_detectOff"
    },
    "recordingTime[h]": 0,
    "detection": {
      "state": false,
      "detectingTime[h]": 0,
      "detectedEvents": 0,
      "aiModel": "trumpet trimmed"
    }
  },
  "device": {
    "firmware": "ELOC_V1.0",
    "Uptime[h]": 0.02,
    "totalRecordingTime[h]": 0,
    "SdCardSize[GB]": 1.83,
    "SdCardFreeSpace[GB]": 1.46,
    "SdCardFreeSpace[%]": 79.71
  }
}}

getStatus ==>

{"id" : -1, "ecode" : 0, "error" : "ESP_OK", "cmd" : "getStatus", "payload" : {
  "battery": {
    "type": "no Battery",
    "state": "Full",
    "SoC[%]": 78.9,
    "voltage[V]": 3.31
  },
  "session": {
    "identifier": "not_set1709758728105",
    "recordingState": {
      "val": 2,
      "state": "recordOn_detectOff"
    },
    "recordingTime[h]": 0.04,
    "detection": {
      "state": false,
      "detectingTime[h]": 0,
      "detectedEvents": 0,
      "aiModel": "trumpet trimmed"
    }
  },
  "device": {
    "firmware": "ELOC_V1.0",
    "Uptime[h]": 0.08,
    "totalRecordingTime[h]": 0.04,
    "SdCardSize[GB]": 1.83,
    "SdCardFreeSpace[GB]": 1.46,
    "SdCardFreeSpace[%]": 79.5
  }
}}

EDsteve commented 3 months ago

@josephx86 @LIFsCode @OOHehir

We still need to get to the bottom of the time synch errors.

Sending getStatus 16 times in a short span of time is definitely inefficient. The app requests info from the board depending on > UI events, so I will refactor the code and reduce the number of requests.

When i connect the app with the ELOC. I don't request anything. But in the firmware log i can see that requests are sent (or at least it looks like it). Sometimes 16 times (as experienced above), sometimes 4 times and sometimes 6 times. It's kind of random. @josephx86 Which UI events could request getStatus automatically without interaction?

Firmware synchs 1970 time from phone without error:

(Not sure if related to above but i post it here for now.)

I (34891) BtCmds: timestamp in from type ? Time Zone: 7 sec: 0 millisec: 0
I (34895) BtCmds: new timestamp from new sys time (local time) 25200000
I (34902) BtCmds: new timestamp from timeobJect (local time) 25200007
W (35577) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 798, status 0x0
W (37218) BT_HCI: hcif ssr evt: st 0x0, hdl 0x80, tx_lat 798 rx_lat 798
I (34909) BtCmds: new time set to (local time) Thu, Jan 01 1970 07:00:04

Here is the complete log: 1970 time and too many getStatus.txt

There is no error, but phone synchs time from 1970? Not sure how that is possible. That seems to happen only on one of my phones (which usually worked fine before, using the app from Playstore). For me also not clear if that is a problem from the app or from the FW.

EDsteve commented 3 months ago

@LIFsCode @OOHehir

While @josephx86 has made changes to make the timy synch more fail-safe, he found out that the response from the Firmware returns a different time, which seems strange.

The App sends seconds:1710682419 but the firmware returns: 1310635197 (which is a date from 2011)

I (898220) BtCmds: updating time with {"seconds":1710682419, "ms":0 ,"timezone" : 7}
I (898232) BtCmds: timestamp in from type ? Time Zone: 7 sec: 1710682419 millisec: 0
I (898239) BtCmds: new timestamp from new sys time (local time) 1710707619000
I (898245) BtCmds: new timestamp from timeobJect (local time) 1310635197
I (898252) BtCmds: new time set to (local time) Sun, Mar 17 2024 20:33:39

The ELOC does have the correct time after that. But maybe good to have the correct time in the response.

LIFsCode commented 3 months ago

@edsteve That is a integer resolution problem. I w'll fix this.

OOHehir commented 3 months ago

@EDsteve I was trying to test the functionality of setting the ELOC from the Android app but couldn't find it. Am I missing something?

EDsteve commented 3 months ago

@OOHehir You mean you couldn't find the app in the Playstore? Searching for ELOC doesn't bring up the correct app? Will need to do some SEO i guess. Haha Here is the link to the ELOC app

EDIT: Google Sign In still have some issues. So register with an email for now. The app in the Playstore still sends too many requests after connecting to the ELOC (sometimes). Joseph has fixed that already but i am on the road since a few days and not able to test and update the new app yet.

EDsteve commented 3 months ago

@josephx86 has fixed all issues regarding time synch from app

the 1970 issue happened only from specific phones which can't connect to time servers -> Only local phone time is synched now to the ELOC
The issues with too many requests after connectin to the ELOC via BT is resolved
Time synch procedure is more rigid

@LIFsCode has fixed the time-response time with 81eff2b9b891d80a43b3f239c870f6d4e7e1fdb9

I have tested all and woks fine so far -> Closing this issue

@OOHehir the new app should work fine. Also the Google Sign in worked on my side with the updated version.

OOHehir commented 3 months ago

@EDsteve OK, I see there was a new version of the app. I'll try that

EDsteve commented 3 months ago

@OOHehir I accidentaly uploaded the older version. In a few hours a new version should be available. Please check the Playstore and update the app to avoid multiple request after BT connection

LIFsCode / ELOC-3.0