You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
I have searched the issue tracker for a similar issue and not found a similar issue.
IDF version.
v4.4.4-439-gc25d92074e
Operating System used.
macOS
How did you build your project?
Command line with idf.py
If you are using Windows, please specify command line type.
None
Development Kit.
Custom Hardware
Power Supply used.
USB
What is the expected behavior?
I expect the system time as reported by gettimeofday() to remain fairly accurate during continuous operation of the ESP32 in a communication device that uses the Bluetooth Classic Handsfree Client Protocol to connect to a cellphone.
What is the actual behavior?
Under poor Bluetooth conditions (the phone is at the very edge of Bluetooth range) then the time clock running on the ESP32 can lose many tens of seconds per hour of real time.
This does not occur when the Bluetooth connection is good (e.g. the phone is in the same room as the device) or not present (e.g. the phone is so remote that the ESP32 can never connect).
See "More Information" for additional details.
Steps to reproduce.
The program is designed to run continuously (the ESP32 is not put to sleep at any time). When not connected to a Bluetooth device it will attempt a connection every minute. The following assumes the device has been paired with a cellphone (iPhone 13 iOS 16.6.1).
Set the ESP32 time clock using settimeofday(). At the same time set the time in an accurate battery-backed RTC chip attached to the ESP32.
Locate the cellphone in another room (perhaps 20-25m away with two intervening walls and an intervening floor)
The program attempts to connect and if successful it attempts to maintain a Bluetooth connection with the cellphone.
Once per hour compare the ESP32 time clock time obtained with gettimeofday() with that of the external hardware RTC chip. Display an error message and correct the ESP32 time clock if it is more than 10 seconds different.
The external hardware RTC chip has been verified to hold the correct time.
Debug Logs.
ELF file SHA256: b3778f3f1e013f3a
Rebooting...
ets Jul 29 2019 12:21:46
rst:0xc (SW_CPU_RESET),boot:0x1f (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:6968
load:0x40078000,len:15792
load:0x40080400,len:4516
0x40080400: _init at ??:?
entry 0x400806b8
I (27) boot: ESP-IDF v4.4.4-439-gc25d92074e 2nd stage bootloader
I (27) boot: compile time 18:58:16
I (27) boot: chip revision: v3.0
I (32) qio_mode: Enabling default flash chip QIO
I (37) boot.esp32: SPI Speed : 80MHz
I (42) boot.esp32: SPI Mode : QIO
I (46) boot.esp32: SPI Flash Size : 16MB
I (51) boot: Enabling RNG early entropy source...
I (56) boot: Partition Table:
I (60) boot: ## Label Usage Type ST Offset Length
I (67) boot: 0 nvs WiFi data 01 02 00009000 00004000
I (74) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (82) boot: 2 factory factory app 00 00 00010000 00300000
I (89) boot: End of partition table
I (94) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=5ae68h (372328) map
I (205) esp_image: segment 1: paddr=0006ae90 vaddr=3ffbdb60 size=04258h ( 16984) load
I (210) esp_image: segment 2: paddr=0006f0f0 vaddr=40080000 size=00f28h ( 3880) load
I (212) esp_image: segment 3: paddr=00070020 vaddr=400d0020 size=ace8ch (708236) map
I (414) esp_image: segment 4: paddr=0011ceb4 vaddr=40080f28 size=19b60h (105312) load
I (461) boot: Loaded app from partition at offset 0x10000
I (461) boot: Disabling RNG early entropy source...
I (473) psram: This chip is ESP32-D0WD
I (473) spiram: Found 64MBit SPI RAM device
I (474) spiram: SPI RAM mode: flash 80m sram 40m
I (479) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (486) cpu_start: Pro cpu up.
I (490) cpu_start: Starting app cpu, entry point is 0x40081474
0x40081474: call_start_cpu1 at /Users/danjulio/esp/esp-idf-v4.4/components/esp_system/port/cpu_start.c:147
I (483) cpu_start: App cpu up.
...
E (25205186) gcore_task: Correcting ESP32 time (delta = -54)
I (25205196) time_utilities: Set time: Wed Sep 20, 2023 4:49:40 (epoch secs: 1695185380)
W (25206736) BT_SDP: SDP - Rcvd conn cnf with error: 0x4 CID 0x40
W (25206736) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
I (25206736) bt_gap: event: 16
I (25206736) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (25206746) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (25259196) bt_task: Found 1 bonded device(s)
I (25259196) bt_task: Attempting to connect to Dan’s iPhone:
I (25259196) bt_task: fc aa 81 f1 0c 86
W (25260616) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
I (25260616) bt_gap: event: 16
E (25261716) BT_BTM: tBTM_SEC_DEV:0x3ffe3ac4 rs_disc_pending=0
W (25261736) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 32000
W (25261756) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (25261896) BT_APPL: new conn_srvc id:27, app_id:1
W (25261896) BT_APPL: bta_dm_pm_ssr conn_srvc id:27, app_id:1
W (25261896) BT_APPL: bta_dm_pm_ssr:2, lat:1200
I (25261906) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (25261906) bt_hf: --connection state connected, peer feats 0x0, chld_feats 0x0
I (25262096) bt_hf: APP HFP event: NETWORK_STATE_EVT
I (25262096) bt_hf: --NETWORK STATE available
I (25262096) bt_hf: APP HFP event: CALL_IND_EVT
I (25262106) bt_hf: --Call indicator NO call in progress
I (25262106) bt_hf: APP HFP event: CALL_SETUP_IND_EVT
I (25262116) bt_hf: --Call setup indicator NONE
I (25262116) bt_hf: APP HFP event: BATTERY_LEVEL_IND_EVT
I (25262126) bt_hf: --battery level 5
I (25262126) bt_hf: APP HFP event: SIGNAL_STRENGTH_IND_EVT
I (25262136) bt_hf: -- signal strength: 1
I (25262146) bt_hf: APP HFP event: ROAMING_STATUS_IND_EVT
I (25262146) bt_hf: --ROAMING: inactive
I (25262156) bt_hf: APP HFP event: CALL_HELD_IND_EVT
I (25262156) bt_hf: --Call held indicator NONE held
I (25262166) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (25262176) bt_hf: --connection state slc_connected, peer feats 0xfef, chld_feats 0x3f
I (25262176) bt_hf: APP HFP event: INBAND_RING_TONE_EVT
I (25262186) bt_hf: --inband ring state Provided
I (25262186) bt_task: DISCONNECTED->CONNECTED-IDLE
I (25262216) app_task: DISCONNECTED->CONNECTED_IDLE
I (25265266) gcore_task: Vusb: 5.11v, Iusb: 235mA, Vbatt: 4.18v, Iload: 236mA, Chg: 2
W (25269096) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
E (25292156) BT_APPL: HFPClient: AT response timeout, disconnecting
W (25295156) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:0 state 3 closed: Closed (res: 19)
W (25295166) BT_APPL: BTA_HF_CLIENT_SCO_SHUTDOWN_ST: Ignoring event 3
I (25295166) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (25295176) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (25295186) bt_task: CONNECTED-IDLE->DISCONNECTED
I (25295206) bt_task: Found 1 bonded device(s)
I (25295206) bt_task: Attempting to connect to Dan’s iPhone:
I (25295206) bt_task: fc aa 81 f1 0c 86
W (25295206) BT_APPL: HF Client found collision (RFCOMM) ...
I (25295236) app_task: CONNECTED_IDLE->DISCONNECTED
W (25297286) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0xc
E (25297286) BT_APPL: bta_dm_pm_btm_status hci_status=12
I (25297286) bt_gap: ESP_BT_GAP_MODE_CHG_EVT mode:0
W (25297356) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x22
W (25298856) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
I (25298856) bt_gap: event: 16
E (25300106) BT_BTM: tBTM_SEC_DEV:0x3ffe3ac4 rs_disc_pending=0
W (25300116) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 32000
W (25300166) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (25300246) BT_APPL: new conn_srvc id:27, app_id:1
W (25300246) BT_APPL: bta_dm_pm_ssr conn_srvc id:27, app_id:1
W (25300246) BT_APPL: bta_dm_pm_ssr:2, lat:1200
I (25300246) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (25300256) bt_hf: --connection state connected, peer feats 0x0, chld_feats 0x0
I (25300376) bt_hf: APP HFP event: NETWORK_STATE_EVT
I (25300376) bt_hf: --NETWORK STATE available
I (25300376) bt_hf: APP HFP event: CALL_IND_EVT
I (25300376) bt_hf: --Call indicator NO call in progress
I (25300386) bt_hf: APP HFP event: CALL_SETUP_IND_EVT
I (25300396) bt_hf: --Call setup indicator NONE
I (25300396) bt_hf: APP HFP event: BATTERY_LEVEL_IND_EVT
I (25300406) bt_hf: --battery level 5
I (25300406) bt_hf: APP HFP event: SIGNAL_STRENGTH_IND_EVT
I (25300416) bt_hf: -- signal strength: 1
I (25300416) bt_hf: APP HFP event: ROAMING_STATUS_IND_EVT
I (25300426) bt_hf: --ROAMING: inactive
I (25300426) bt_hf: APP HFP event: CALL_HELD_IND_EVT
I (25300436) bt_hf: --Call held indicator NONE held
I (25300436) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (25300446) bt_hf: --connection state slc_connected, peer feats 0xfef, chld_feats 0x3f
I (25300456) bt_hf: APP HFP event: INBAND_RING_TONE_EVT
I (25300456) bt_hf: --inband ring state Provided
I (25300466) bt_task: DISCONNECTED->CONNECTED-IDLE
I (25300516) app_task: DISCONNECTED->CONNECTED_IDLE
W (25307446) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
I (25325366) gcore_task: Vusb: 5.11v, Iusb: 235mA, Vbatt: 4.18v, Iload: 237mA, Chg: 2
E (25330416) BT_APPL: HFPClient: AT response timeout, disconnecting
W (25333416) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:0 state 3 closed: Closed (res: 19)
W (25333426) BT_APPL: BTA_HF_CLIENT_SCO_SHUTDOWN_ST: Ignoring event 3
I (25333426) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (25333436) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (25333446) bt_task: CONNECTED-IDLE->DISCONNECTED
I (25333466) app_task: CONNECTED_IDLE->DISCONNECTED
I (25333466) bt_task: Found 1 bonded device(s)
I (25333466) bt_task: Attempting to connect to Dan’s iPhone:
I (25333466) bt_task: fc aa 81 f1 0c 86
W (25333476) BT_APPL: HF Client found collision (RFCOMM) ...
W (25335526) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0xc
E (25335526) BT_APPL: bta_dm_pm_btm_status hci_status=12
I (25335526) bt_gap: ESP_BT_GAP_MODE_CHG_EVT mode:0
W (25335596) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x22
W (25337186) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
I (25337186) bt_gap: event: 16
W (25358676) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:0 state 1 closed: Peer connection failed (res: 16)
W (25358676) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x8
I (25358676) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (25358686) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (25385366) gcore_task: Vusb: 5.15v, Iusb: 181mA, Vbatt: 4.18v, Iload: 182mA, Chg: 2
THIS SECTION CUT OUT BUT IT IS MORE OF THE SAME
I (28275346) bt_task: Found 1 bonded device(s)
I (28275346) bt_task: Attempting to connect to Dan’s iPhone:
I (28275346) bt_task: fc aa 81 f1 0c 86
W (28275946) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
I (28275946) bt_gap: event: 16
E (28277186) BT_BTM: tBTM_SEC_DEV:0x3ffe3ac4 rs_disc_pending=0
W (28277196) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 32000
W (28277386) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (28277546) BT_APPL: new conn_srvc id:27, app_id:1
W (28277546) BT_APPL: bta_dm_pm_ssr conn_srvc id:27, app_id:1
W (28277546) BT_APPL: bta_dm_pm_ssr:2, lat:1200
I (28277546) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28277556) bt_hf: --connection state connected, peer feats 0x0, chld_feats 0x0
I (28277706) bt_hf: APP HFP event: NETWORK_STATE_EVT
I (28277706) bt_hf: --NETWORK STATE available
I (28277706) bt_hf: APP HFP event: CALL_IND_EVT
I (28277716) bt_hf: --Call indicator NO call in progress
I (28277716) bt_hf: APP HFP event: CALL_SETUP_IND_EVT
I (28277726) bt_hf: --Call setup indicator NONE
I (28277726) bt_hf: APP HFP event: BATTERY_LEVEL_IND_EVT
I (28277736) bt_hf: --battery level 5
I (28277746) bt_hf: APP HFP event: SIGNAL_STRENGTH_IND_EVT
I (28277746) bt_hf: -- signal strength: 1
I (28277756) bt_hf: APP HFP event: ROAMING_STATUS_IND_EVT
I (28277756) bt_hf: --ROAMING: inactive
I (28277766) bt_hf: APP HFP event: CALL_HELD_IND_EVT
I (28277766) bt_hf: --Call held indicator NONE held
I (28277886) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28277886) bt_hf: --connection state slc_connected, peer feats 0xfef, chld_feats 0x3f
I (28277886) bt_hf: APP HFP event: INBAND_RING_TONE_EVT
I (28277896) bt_hf: --inband ring state Provided
I (28277906) bt_task: DISCONNECTED->CONNECTED-IDLE
I (28277926) app_task: DISCONNECTED->CONNECTED_IDLE
W (28284746) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
E (28307876) BT_APPL: HFPClient: AT response timeout, disconnecting
W (28310876) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:0 state 3 closed: Closed (res: 19)
W (28310876) BT_APPL: BTA_HF_CLIENT_SCO_SHUTDOWN_ST: Ignoring event 3
I (28310886) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28310886) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (28310896) bt_task: CONNECTED-IDLE->DISCONNECTED
I (28310926) app_task: CONNECTED_IDLE->DISCONNECTED
I (28310926) bt_task: Found 1 bonded device(s)
I (28310926) bt_task: Attempting to connect to Dan’s iPhone:
I (28310926) bt_task: fc aa 81 f1 0c 86
W (28310936) BT_APPL: HF Client found collision (RFCOMM) ...
I (28327146) gcore_task: Vusb: 5.11v, Iusb: 233mA, Vbatt: 4.18v, Iload: 234mA, Chg: 2
W (28337616) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x22
I (28337616) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28337616) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (28370936) bt_task: Found 1 bonded device(s)
I (28370936) bt_task: Attempting to connect to Dan’s iPhone:
I (28370936) bt_task: fc aa 81 f1 0c 86
W (28376066) BT_SDP: SDP - Rcvd conn cnf with error: 0x4 CID 0x40
W (28376066) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
I (28376066) bt_gap: event: 16
I (28376066) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28376076) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (28387146) gcore_task: Vusb: 5.15v, Iusb: 181mA, Vbatt: 4.18v, Iload: 182mA, Chg: 2
I (28430946) bt_task: Found 1 bonded device(s)
I (28430946) bt_task: Attempting to connect to Dan’s iPhone:
I (28430946) bt_task: fc aa 81 f1 0c 86
W (28435246) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
I (28435246) bt_gap: event: 16
I (28447146) gcore_task: Vusb: 5.11v, Iusb: 231mA, Vbatt: 4.18v, Iload: 233mA, Chg: 2
W (28457296) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x13
I (28457296) bt_gap: event: 17
W (28458476) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
I (28458476) bt_gap: event: 16
W (28482756) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:0 state 1 closed: Peer connection failed (res: 16)
W (28482756) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x13
I (28482766) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28482766) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (28490956) bt_task: Found 1 bonded device(s)
I (28490956) bt_task: Attempting to connect to Dan’s iPhone:
I (28490956) bt_task: fc aa 81 f1 0c 86
W (28491846) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
I (28491846) bt_gap: event: 16
E (28492956) BT_BTM: tBTM_SEC_DEV:0x3ffe3ac4 rs_disc_pending=0
W (28493026) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 32000
W (28493066) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (28493156) BT_APPL: new conn_srvc id:27, app_id:1
W (28493156) BT_APPL: bta_dm_pm_ssr conn_srvc id:27, app_id:1
W (28493156) BT_APPL: bta_dm_pm_ssr:2, lat:1200
I (28493156) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28493166) bt_hf: --connection state connected, peer feats 0x0, chld_feats 0x0
I (28493256) bt_hf: APP HFP event: NETWORK_STATE_EVT
I (28493256) bt_hf: --NETWORK STATE available
I (28493256) bt_hf: APP HFP event: CALL_IND_EVT
I (28493256) bt_hf: --Call indicator NO call in progress
I (28493266) bt_hf: APP HFP event: CALL_SETUP_IND_EVT
I (28493266) bt_hf: --Call setup indicator NONE
I (28493276) bt_hf: APP HFP event: BATTERY_LEVEL_IND_EVT
I (28493286) bt_hf: --battery level 5
I (28493286) bt_hf: APP HFP event: SIGNAL_STRENGTH_IND_EVT
I (28493296) bt_hf: -- signal strength: 1
I (28493296) bt_hf: APP HFP event: ROAMING_STATUS_IND_EVT
I (28493306) bt_hf: --ROAMING: inactive
I (28493306) bt_hf: APP HFP event: CALL_HELD_IND_EVT
I (28493316) bt_hf: --Call held indicator NONE held
I (28493316) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28493326) bt_hf: --connection state slc_connected, peer feats 0xfef, chld_feats 0x3f
I (28493336) bt_hf: APP HFP event: INBAND_RING_TONE_EVT
I (28493336) bt_hf: --inband ring state Provided
I (28493346) bt_task: DISCONNECTED->CONNECTED-IDLE
I (28493396) app_task: DISCONNECTED->CONNECTED_IDLE
W (28500356) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
I (28507196) gcore_task: Vusb: 5.11v, Iusb: 234mA, Vbatt: 4.18v, Iload: 236mA, Chg: 2
E (28523276) BT_APPL: HFPClient: AT response timeout, disconnecting
W (28526276) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:0 state 3 closed: Closed (res: 19)
W (28526276) BT_APPL: BTA_HF_CLIENT_SCO_SHUTDOWN_ST: Ignoring event 3
I (28526276) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28526286) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (28526296) bt_task: CONNECTED-IDLE->DISCONNECTED
I (28526316) bt_task: Found 1 bonded device(s)
I (28526316) bt_task: Attempting to connect to Dan’s iPhone:
I (28526316) bt_task: fc aa 81 f1 0c 86
W (28526316) BT_APPL: HF Client found collision (RFCOMM) ...
I (28526346) app_task: CONNECTED_IDLE->DISCONNECTED
W (28553166) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x22
I (28553166) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28553166) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (28567196) gcore_task: Vusb: 5.15v, Iusb: 181mA, Vbatt: 4.18v, Iload: 182mA, Chg: 2
I (28586326) bt_task: Found 1 bonded device(s)
I (28586326) bt_task: Attempting to connect to Dan’s iPhone:
I (28586326) bt_task: fc aa 81 f1 0c 86
W (28591456) BT_SDP: SDP - Rcvd conn cnf with error: 0x4 CID 0x41
W (28591456) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
I (28591456) bt_gap: event: 16
I (28591456) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28591466) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (28627196) gcore_task: Vusb: 5.15v, Iusb: 181mA, Vbatt: 4.18v, Iload: 182mA, Chg: 2
I (28646336) bt_task: Found 1 bonded device(s)
I (28646336) bt_task: Attempting to connect to Dan’s iPhone:
I (28646336) bt_task: fc aa 81 f1 0c 86
W (28651466) BT_SDP: SDP - Rcvd conn cnf with error: 0x4 CID 0x40
W (28651466) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
I (28651466) bt_gap: event: 16
I (28651466) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28651476) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (28687196) gcore_task: Vusb: 5.15v, Iusb: 181mA, Vbatt: 4.17v, Iload: 182mA, Chg: 2
I (28706346) bt_task: Found 1 bonded device(s)
I (28706346) bt_task: Attempting to connect to Dan’s iPhone:
I (28706346) bt_task: fc aa 81 f1 0c 86
W (28707306) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
I (28707306) bt_gap: event: 16
E (28708996) BT_BTM: tBTM_SEC_DEV:0x3ffe3ac4 rs_disc_pending=0
W (28709046) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 32000
W (28709166) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (28709206) BT_APPL: new conn_srvc id:27, app_id:1
W (28709206) BT_APPL: bta_dm_pm_ssr conn_srvc id:27, app_id:1
W (28709206) BT_APPL: bta_dm_pm_ssr:2, lat:1200
I (28709216) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28709216) bt_hf: --connection state connected, peer feats 0x0, chld_feats 0x0
I (28709296) bt_hf: APP HFP event: NETWORK_STATE_EVT
I (28709296) bt_hf: --NETWORK STATE available
I (28709296) bt_hf: APP HFP event: CALL_IND_EVT
I (28709296) bt_hf: --Call indicator NO call in progress
I (28709306) bt_hf: APP HFP event: CALL_SETUP_IND_EVT
I (28709316) bt_hf: --Call setup indicator NONE
I (28709316) bt_hf: APP HFP event: BATTERY_LEVEL_IND_EVT
I (28709326) bt_hf: --battery level 5
I (28709326) bt_hf: APP HFP event: SIGNAL_STRENGTH_IND_EVT
I (28709336) bt_hf: -- signal strength: 1
I (28709336) bt_hf: APP HFP event: ROAMING_STATUS_IND_EVT
I (28709346) bt_hf: --ROAMING: inactive
I (28709346) bt_hf: APP HFP event: CALL_HELD_IND_EVT
I (28709356) bt_hf: --Call held indicator NONE held
I (28709356) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28709366) bt_hf: --connection state slc_connected, peer feats 0xfef, chld_feats 0x3f
I (28709376) bt_hf: APP HFP event: INBAND_RING_TONE_EVT
I (28709376) bt_hf: --inband ring state Provided
I (28709386) bt_task: DISCONNECTED->CONNECTED-IDLE
I (28709436) app_task: DISCONNECTED->CONNECTED_IDLE
W (28716406) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
E (28739336) BT_APPL: HFPClient: AT response timeout, disconnecting
W (28742336) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:0 state 3 closed: Closed (res: 19)
W (28742336) BT_APPL: BTA_HF_CLIENT_SCO_SHUTDOWN_ST: Ignoring event 3
I (28742336) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28742346) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (28742356) bt_task: CONNECTED-IDLE->DISCONNECTED
I (28742376) bt_task: Found 1 bonded device(s)
I (28742376) bt_task: Attempting to connect to Dan’s iPhone:
I (28742376) bt_task: fc aa 81 f1 0c 86
W (28742376) BT_APPL: HF Client found collision (RFCOMM) ...
I (28742386) app_task: CONNECTED_IDLE->DISCONNECTED
I (28747236) gcore_task: Vusb: 5.11v, Iusb: 235mA, Vbatt: 4.18v, Iload: 236mA, Chg: 2
W (28769326) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x22
I (28769326) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28769326) bt_hf: --connection state disconnected, peer feats 0x0, chld_feats 0x0
I (28802386) bt_task: Found 1 bonded device(s)
I (28802386) bt_task: Attempting to connect to Dan’s iPhone:
I (28802386) bt_task: fc aa 81 f1 0c 86
W (28802816) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
I (28802816) bt_gap: event: 16
E (28804026) BT_BTM: tBTM_SEC_DEV:0x3ffe3ac4 rs_disc_pending=0
W (28804036) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 32000
W (28804176) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (28804226) BT_APPL: new conn_srvc id:27, app_id:1
W (28804226) BT_APPL: bta_dm_pm_ssr conn_srvc id:27, app_id:1
W (28804226) BT_APPL: bta_dm_pm_ssr:2, lat:1200
I (28804236) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28804236) bt_hf: --connection state connected, peer feats 0x0, chld_feats 0x0
I (28804366) bt_hf: APP HFP event: NETWORK_STATE_EVT
I (28804366) bt_hf: --NETWORK STATE available
I (28804366) bt_hf: APP HFP event: CALL_IND_EVT
I (28804376) bt_hf: --Call indicator NO call in progress
I (28804376) bt_hf: APP HFP event: CALL_SETUP_IND_EVT
I (28804386) bt_hf: --Call setup indicator NONE
I (28804386) bt_hf: APP HFP event: BATTERY_LEVEL_IND_EVT
I (28804396) bt_hf: --battery level 5
I (28804396) bt_hf: APP HFP event: SIGNAL_STRENGTH_IND_EVT
I (28804406) bt_hf: -- signal strength: 1
I (28804406) bt_hf: APP HFP event: ROAMING_STATUS_IND_EVT
I (28804416) bt_hf: --ROAMING: inactive
I (28804416) bt_hf: APP HFP event: CALL_HELD_IND_EVT
I (28804426) bt_hf: --Call held indicator NONE held
I (28804436) bt_hf: APP HFP event: CONNECTION_STATE_EVT
I (28804436) bt_hf: --connection state slc_connected, peer feats 0xfef, chld_feats 0x3f
I (28804446) bt_hf: APP HFP event: INBAND_RING_TONE_EVT
I (28804456) bt_hf: --inband ring state Provided
I (28804456) bt_task: DISCONNECTED->CONNECTED-IDLE
I (28804506) app_task: DISCONNECTED->CONNECTED_IDLE
I (28807306) gcore_task: Vusb: 5.11v, Iusb: 235mA, Vbatt: 4.18v, Iload: 237mA, Chg: 2
E (28807306) gcore_task: Correcting ESP32 time (delta = -54)
I (28807316) time_utilities: Set time: Wed Sep 20, 2023 5:49:42 (epoch secs: 1695188982)
More Information.
The log file contains a section of an overnight run showing approximately 1 hour of elapsed time during which the ESP32 loses 54 seconds (it is 54 seconds slower than the hardware RTC). [NOTE I had to cut out some of the log file to post this]. Interestingly the log file millisecond time stamps do appear to be keeping accurate time. At time 25205186 mSec the code corrects the ESP32 time clock. For the next hour you can see it struggles to maintain a connection with the phone. About one hour later, at 28807306 mSec, it checks the ESP32 time clock against the RTC and finds it is 54 seconds slow.
My Bluetooth code is based on the Espressif Bluetooth Classic Handsfree client demo code and I retained the logging information for the various GAP (bt_gap) and HF (bt_hf) callbacks that you can see in the log file. My bluetooth handling code can be found here: BT Task.
Again, if the devices are physically close and the Bluetooth SLC remains valid or if the devices are too far apart (or the device pairing information is deleted) then the clock maintains accurate time. It seems only when the Bluetooth stack is struggling to maintain a connection does the clock slow down (it never runs fast).
The text was updated successfully, but these errors were encountered:
github-actionsbot
changed the title
ESP32 Time Clock runs slow under certain conditions with Bluetooth Classic HF client
ESP32 Time Clock runs slow under certain conditions with Bluetooth Classic HF client (IDFGH-11110)
Sep 20, 2023
Sleep is not used. ESP32 is running 100% of the time.
It is seen during periods of time where the Bluetooth stack is having difficulty maintaining a connection with the cellphone (long distance). It is disconnecting and attempting to reconnect frequently. If cellphone is close or completely absent then there is no problem.
I realize this is not a very detailed description. Please let me know if I can provide more data.
Answers checklist.
IDF version.
v4.4.4-439-gc25d92074e
Operating System used.
macOS
How did you build your project?
Command line with idf.py
If you are using Windows, please specify command line type.
None
Development Kit.
Custom Hardware
Power Supply used.
USB
What is the expected behavior?
I expect the system time as reported by gettimeofday() to remain fairly accurate during continuous operation of the ESP32 in a communication device that uses the Bluetooth Classic Handsfree Client Protocol to connect to a cellphone.
What is the actual behavior?
Under poor Bluetooth conditions (the phone is at the very edge of Bluetooth range) then the time clock running on the ESP32 can lose many tens of seconds per hour of real time.
This does not occur when the Bluetooth connection is good (e.g. the phone is in the same room as the device) or not present (e.g. the phone is so remote that the ESP32 can never connect).
See "More Information" for additional details.
Steps to reproduce.
The program is designed to run continuously (the ESP32 is not put to sleep at any time). When not connected to a Bluetooth device it will attempt a connection every minute. The following assumes the device has been paired with a cellphone (iPhone 13 iOS 16.6.1).
The external hardware RTC chip has been verified to hold the correct time.
Debug Logs.
More Information.
The log file contains a section of an overnight run showing approximately 1 hour of elapsed time during which the ESP32 loses 54 seconds (it is 54 seconds slower than the hardware RTC). [NOTE I had to cut out some of the log file to post this]. Interestingly the log file millisecond time stamps do appear to be keeping accurate time. At time 25205186 mSec the code corrects the ESP32 time clock. For the next hour you can see it struggles to maintain a connection with the phone. About one hour later, at 28807306 mSec, it checks the ESP32 time clock against the RTC and finds it is 54 seconds slow.
My Bluetooth code is based on the Espressif Bluetooth Classic Handsfree client demo code and I retained the logging information for the various GAP (bt_gap) and HF (bt_hf) callbacks that you can see in the log file. My bluetooth handling code can be found here: BT Task.
Again, if the devices are physically close and the Bluetooth SLC remains valid or if the devices are too far apart (or the device pairing information is deleted) then the clock maintains accurate time. It seems only when the Bluetooth stack is struggling to maintain a connection does the clock slow down (it never runs fast).
The text was updated successfully, but these errors were encountered: