Badge sometimes send old chunks or empty chunks

[OrenLederman]

I noticed that the badge sometimes send data older than the timestamp we ask for. In fact, it seems to does that when:

1. After the badge reset and recording hasn't been started yet it will send an empty chunk (timestamp = 0)
2. After the badge stopped recording, it will send a date from some recent chunk, even if it's earlier than the time requested (see example log below)

Be careful if you decide to change anything in this mechanism.. if it's not something very obvious we'll might need to just keep it as an open bug

One workaround, is to start recording before pulling new data. In fact,t hat is what we do with the phone hub, which might explain why we haven't noticed this before.

Example:

2016-08-28 11:16:27,789 - INFO - Resetting BLE 2016-08-28 11:16:29,801 - INFO - Done resetting BLE 2016-08-28 11:16:29,801 - INFO - Started 2016-08-28 11:16:29,802 - INFO - Will request data since 1472397389.000000 2016-08-28 11:16:29,802 - INFO - Scanning for devices... 2016-08-28 11:16:29,802 - INFO - Reading whitelist: 2016-08-28 11:16:29,805 - INFO - F9:A0:3E:12:9E:3E 2016-08-28 11:16:32,823 - DEBUG - Found E7:00:28:A7:DB:C2, but not on whitelist. Device info: {'rssi': -68, 'scan_date': datetime.datetime(2016, 8, 28, 11, 16, 32, 822945), 'adv_payload': {'proximity_status': 0, 'sync_status': 0, 'audio_status': 0, 'mac': [231, 0, 40, 167, 219, 194], 'badge_id': 63880, 'voltage': 2.75, 'status_flags': 0, 'project_id': 0}} 2016-08-28 11:16:32,824 - DEBUG - Found F9:A0:3E:12:9E:3E, added. Device info: {'rssi': -78, 'scan_date': datetime.datetime(2016, 8, 28, 11, 16, 32, 823176), 'adv_payload': {'proximity_status': 0, 'sync_status': 1, 'audio_status': 0, 'mac': [249, 160, 62, 18, 158, 62], 'badge_id': 830, 'voltage': 2.7, 'status_flags': 1, 'project_id': 0}} 2016-08-28 11:16:34,826 - DEBUG - Unseen device. Adding to dict: F9:A0:3E:12:9E:3E 2016-08-28 11:16:34,827 - INFO - [F9:A0:3E:12:9E:3E] Connecting to F9:A0:3E:12:9E:3E 2016-08-28 11:16:36,092 - INFO - [F9:A0:3E:12:9E:3E] Connected 2016-08-28 11:16:36,302 - INFO - [F9:A0:3E:12:9E:3E] Got status 2016-08-28 11:16:36,302 - INFO - [F9:A0:3E:12:9E:3E] Badge datetime was: 1472397396,111, Voltage: 2.70615839958 2016-08-28 11:16:36,302 - INFO - [F9:A0:3E:12:9E:3E] Requesting data since 1472397389 802.085 2016-08-28 11:16:36,443 - INFO - [F9:A0:3E:12:9E:3E] finished reading data 2016-08-28 11:16:36,443 - INFO - [F9:A0:3E:12:9E:3E] Requesting scans since 1472397389 2016-08-28 11:16:36,589 - INFO - [F9:A0:3E:12:9E:3E] finished reading data 2016-08-28 11:16:36,589 - DEBUG - [F9:A0:3E:12:9E:3E] Setting last seen audio chunk to 1472396577.994 2016-08-28 11:16:36,589 - INFO - [F9:A0:3E:12:9E:3E] Disconnecting from F9:A0:3E:12:9E:3E 2016-08-28 11:16:36,591 - INFO - Successfully pulled data 2016-08-28 11:16:36,591 - INFO - Chunks received: 1 2016-08-28 11:16:36,591 - INFO - saving chunks to file 2016-08-28 11:16:36,591 - INFO - CSV: Chunk timestamp: 1472396578.994, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 0 2016-08-28 11:16:36,591 - INFO - done writing 2016-08-28 11:16:36,591 - INFO - No proximity scans ready 2016-08-28 11:16:38,594 - INFO - Sleeping... 2016-08-28 11:16:44,600 - INFO - Scanning for devices... 2016-08-28 11:16:44,601 - INFO - Reading whitelist: 2016-08-28 11:16:44,601 - INFO - F9:A0:3E:12:9E:3E 2016-08-28 11:16:47,731 - DEBUG - Found E7:00:28:A7:DB:C2, but not on whitelist. Device info: {'rssi': -72, 'scan_date': datetime.datetime(2016, 8, 28, 11, 16, 47, 731034), 'adv_payload': {'proximity_status': 0, 'sync_status': 0, 'audio_status': 0, 'mac': [231, 0, 40, 167, 219, 194], 'badge_id': 63880, 'voltage': 2.75, 'status_flags': 0, 'project_id': 0}} 2016-08-28 11:16:47,731 - DEBUG - Found F9:A0:3E:12:9E:3E, added. Device info: {'rssi': -76, 'scan_date': datetime.datetime(2016, 8, 28, 11, 16, 47, 731212), 'adv_payload': {'proximity_status': 0, 'sync_status': 1, 'audio_status': 0, 'mac': [249, 160, 62, 18, 158, 62], 'badge_id': 830, 'voltage': 2.67, 'status_flags': 1, 'project_id': 0}} 2016-08-28 11:16:49,733 - INFO - [F9:A0:3E:12:9E:3E] Connecting to F9:A0:3E:12:9E:3E 2016-08-28 11:16:51,002 - INFO - [F9:A0:3E:12:9E:3E] Connected 2016-08-28 11:16:51,142 - INFO - [F9:A0:3E:12:9E:3E] Got status 2016-08-28 11:16:51,142 - INFO - [F9:A0:3E:12:9E:3E] Badge datetime was: 1472397410,932, Voltage: 2.67448687553 2016-08-28 11:16:51,143 - INFO - [F9:A0:3E:12:9E:3E] Requesting data since 1472396577 994 2016-08-28 11:16:56,253 - INFO - [F9:A0:3E:12:9E:3E] finished reading data 2016-08-28 11:16:56,254 - INFO - [F9:A0:3E:12:9E:3E] Requesting scans since 1472397389 2016-08-28 11:16:56,392 - INFO - [F9:A0:3E:12:9E:3E] finished reading data 2016-08-28 11:16:56,392 - DEBUG - [F9:A0:3E:12:9E:3E] Setting last seen audio chunk to 1472396686.322 2016-08-28 11:16:56,393 - INFO - [F9:A0:3E:12:9E:3E] Disconnecting from F9:A0:3E:12:9E:3E 2016-08-28 11:16:56,393 - INFO - Successfully pulled data 2016-08-28 11:16:56,393 - INFO - Chunks received: 20 2016-08-28 11:16:56,394 - INFO - saving chunks to file 2016-08-28 11:16:56,394 - INFO - CSV: Chunk timestamp: 1472396578.994, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,394 - INFO - CSV: Chunk timestamp: 1472396584.694, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,394 - INFO - CSV: Chunk timestamp: 1472396590.395, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,394 - INFO - CSV: Chunk timestamp: 1472396596.095, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,395 - INFO - CSV: Chunk timestamp: 1472396601.796, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,395 - INFO - CSV: Chunk timestamp: 1472396607.496, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,395 - INFO - CSV: Chunk timestamp: 1472396613.197, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,395 - INFO - CSV: Chunk timestamp: 1472396618.897, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,395 - INFO - CSV: Chunk timestamp: 1472396624.597, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,396 - INFO - CSV: Chunk timestamp: 1472396630.321, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,396 - INFO - CSV: Chunk timestamp: 1472396636.021, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,396 - INFO - CSV: Chunk timestamp: 1472396641.721, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,396 - INFO - CSV: Chunk timestamp: 1472396647.422, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114

[anguslocke]

Fixed the empty chunk bug in newScans branch.

[anguslocke]

At the start of your included logs:

2016-08-28 11:16:27,789 - INFO - Resetting BLE 2016-08-28 11:16:29,801 - INFO - Done resetting BLE 2016-08-28 11:16:29,801 - INFO - Started 2016-08-28 11:16:29,802 - INFO - Will request data since 1472397389.000000

Near the end:

2016-08-28 11:16:49,733 - INFO - [F9:A0:3E:12:9E:3E] Connecting to F9:A0:3E:12:9E:3E 2016-08-28 11:16:51,002 - INFO - [F9:A0:3E:12:9E:3E] Connected 2016-08-28 11:16:51,142 - INFO - [F9:A0:3E:12:9E:3E] Got status 2016-08-28 11:16:51,142 - INFO - [F9:A0:3E:12:9E:3E] Badge datetime was: 1472397410,932, Voltage: 2.67448687553 2016-08-28 11:16:51,143 - INFO - [F9:A0:3E:12:9E:3E] Requesting data since 1472396577 994 2016-08-28 11:16:56,253 - INFO - [F9:A0:3E:12:9E:3E] finished reading data 2016-08-28 11:16:56,254 - INFO - [F9:A0:3E:12:9E:3E] Requesting scans since 1472397389 2016-08-28 11:16:56,392 - INFO - [F9:A0:3E:12:9E:3E] finished reading data 2016-08-28 11:16:56,392 - DEBUG - [F9:A0:3E:12:9E:3E] Setting last seen audio chunk to 1472396686.322 2016-08-28 11:16:56,393 - INFO - [F9:A0:3E:12:9E:3E] Disconnecting from F9:A0:3E:12:9E:3E 2016-08-28 11:16:56,393 - INFO - Successfully pulled data 2016-08-28 11:16:56,393 - INFO - Chunks received: 20 2016-08-28 11:16:56,394 - INFO - saving chunks to file 2016-08-28 11:16:56,394 - INFO - CSV: Chunk timestamp: 1472396578.994, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114 2016-08-28 11:16:56,394 - INFO - CSV: Chunk timestamp: 1472396584.694, Voltage: 2.67448687553, Delay: 50, Samples in chunk: 114

The badge is in fact sending what the server asked for. It's the server that jumped back to an earlier time. So this is either a server bug, or an issue that arose from the bad empty chunks the badge sent. (the empty chunks issue is fixed now)

[anguslocke]

Yep, that's what happened. The badge sent the bad empty chunk, which had some undefined timestamp. And the server updated last_audio_ts to that bad timestamp. (minus 1 second) So it appears the empty chunk fix solves both issues?