Bluetooth (A2DP) and light sleep with iPhone, can't return to light sleep (IDFGH-8727)

[expresspotato]

Answers checklist.

• [X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• [X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• [X] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v4.4.3

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.

No response

Development Kit.

LyraT v4.3

Power Supply used.

USB

What is the expected behavior?

The CPU should return to light sleep, after the audio is paused. It does this with a Galaxy S22+, but not with an iPhone 5s, SE or X.

What is the actual behavior?

The CPU remains active, by virtue of:

// Dev board green LED will show when in light sleep or not gpio_set_direction(GPIO_NUM_22, GPIO_MODE_OUTPUT); gpio_set_level(GPIO_NUM_22, 1); gpio_sleep_sel_en(GPIO_NUM_22);

1. No locks appear to be held by bt after the audio is paused
2. No other locks appear to be held
3. The only running task with any appreciable consumption is btController

Steps to reproduce.

1. Have a 32 kHz crysal or oscillator on your board
2. In menuconfig enable: power management on boot, bluetooth sleep clock 32 kHz crystal, etc.
3. Download the ADF example of A2DP from https://github.com/espressif/esp-adf/tree/master/examples/player/pipeline_a2dp_sink_stream
4. Enable light sleep in main through esp_pm_configure
5. Enable GPIO 22 to be an indicator for light sleep
6. Modify the example to destroy (or stop perhaps) the pipeline when the audio is suspended
7. Notice that when paused / resumed on an S22 (probably more Android phones as well) the, light sleep resumes
8. Notice on iPhone it does not

Debug Logs.

entry 0x400806b4
I (29) boot: ESP-IDF v4.4.3 2nd stage bootloader
I (29) boot: compile time 17:29:26
I (29) boot: chip revision: 3
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 : 8MB
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 phy_init         RF data          01 01 00009000 00001000
I (75) boot:  1 nvs_keys         NVS keys         01 04 0000a000 00001000
I (82) boot:  2 nvs              WiFi data        01 02 0000b000 00004000
I (89) boot:  3 nvs_factory      WiFi data        01 02 0000f000 00004000
I (97) boot:  4 nvs_system       WiFi data        01 02 00013000 00004000
I (104) boot:  5 nvs_user         WiFi data        01 02 00017000 00030000
I (112) boot:  6 otadata          OTA data         01 00 00047000 00002000
I (120) boot:  7 factory          factory app      00 00 00050000 001ca000
I (127) boot:  8 ota_0            OTA app          00 10 00220000 002bc000
I (135) boot:  9 ota_1            OTA app          00 11 004e0000 002bc000
I (142) boot: 10 storage          Unknown data     01 82 0079c000 00040000
I (150) boot: 11 coredump         Unknown data     01 03 007dc000 00020000
I (157) boot: 12 efuse            efuse            01 05 007fc000 00002000
I (165) boot: End of partition table
I (169) boot: Defaulting to factory image
I (174) esp_image: segment 0: paddr=00050020 vaddr=3f400020 size=51158h (332120) map
I (274) esp_image: segment 1: paddr=000a1180 vaddr=3ff80063 size=00008h (     8) load
I (274) esp_image: segment 2: paddr=000a1190 vaddr=3ffbdb60 size=08a70h ( 35440) load
I (290) esp_image: segment 3: paddr=000a9c08 vaddr=40080000 size=06410h ( 25616) load
I (299) esp_image: segment 4: paddr=000b0020 vaddr=400d0020 size=12f1c4h (1241540) map
I (641) esp_image: segment 5: paddr=001df1ec vaddr=40086410 size=16970h ( 92528) load
I (672) esp_image: segment 6: paddr=001f5b64 vaddr=400c0000 size=00064h (   100) load
I (672) esp_image: segment 7: paddr=001f5bd0 vaddr=50000400 size=00010h (    16) load
I (692) boot: Loaded app from partition at offset 0x50000
I (693) boot: Disabling RNG early entropy source...
I (704) psram: This chip is ESP32-D0WD
I (704) spiram: Found 64MBit SPI RAM device
I (704) spiram: SPI RAM mode: flash 80m sram 80m
I (710) spiram: PSRAM initialized, cache is in low/high (2-core) mode.
I (717) cpu_start: Pro cpu up.
I (721) cpu_start: Starting app cpu, entry point is 0x40081710
0x40081710: call_start_cpu1 at /Users/kevin/esp/esp-idf-v4.4.3/components/esp_system/port/cpu_start.c:148

I (0) cpu_start: App cpu up.
I (1223) spiram: SPI SRAM memory test OK
I (1410) cpu_start: Pro cpu start user code
I (1410) cpu_start: cpu freq: 240000000
I (1410) cpu_start: Application information:
I (1413) cpu_start: Project name:     liberty
I (1418) cpu_start: App version:      Liberty One
I (1424) cpu_start: Compile time:     Nov 12 2022 17:29:22
I (1430) cpu_start: ELF file SHA256:  2575268a12efebeb...
I (1436) cpu_start: ESP-IDF:          v4.4.3
I (1441) heap_init: Initializing. RAM available for dynamic allocation:
I (1448) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1454) heap_init: At 3FFB7CD8 len 00000328 (0 KiB): DRAM
I (1461) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1467) heap_init: At 3FFC9010 len 00016FF0 (91 KiB): DRAM
I (1473) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1479) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1486) heap_init: At 4009CD80 len 00003280 (12 KiB): IRAM
I (1492) spiram: Adding pool of 4043K of external SPI memory to heap allocator
I (1501) spi_flash: detected chip: generic
I (1505) spi_flash: flash io: qio
I (1520) pm: Frequency switching config: CPU_MAX: 240, APB_MAX: 240, APB_MIN: 40, Light sleep: DISABLED
I (1520) esp_core_dump_flash: Init core dump to flash
I (1532) esp_core_dump_flash: Found partition 'coredump' @ 7dc000 131072 bytes
I (1560) esp_core_dump_flash: Core dump data checksum is correct
I (1560) esp_core_dump_flash: Found core dump 33476 bytes in flash @ 0x7dc000
I (1563) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
W (1574) LIBERTY: ******** LIBERTY MAIN START ********
I (1584) LIBERTY: --> Running on core: 0
I (1584) pm: Frequency switching config: CPU_MAX: 240, APB_MAX: 240, APB_MIN: 240, Light sleep: ENABLED
I (1664) LIBERTY: --> NVS (user) partition OK
I (1664) LIBERTY: --> NVS (system) partition OK
I (1674) LIBERTY: --> NVS (factory) partition OK
I (1674) LIBERTY: Initializing SPIFFS
E (1674) SPIFFS: mount failed, -10025
E (1674) LIBERTY: Failed to mount or format filesystem
E (1684) LIBERTY: 8 Bit --> 4331451
E (1684) LIBERTY: Internal --> 203556
E (1694) LIBERTY: SPI RAM --> 4138671
E (1694) LIBERTY: Largest free block in Internal --> 110592
E (1704) LIBERTY: Largest free block in SPI RAM --> 4128768
I (1704) LIBERTY: Wakup reason (booted)
I (1714) LIBERTY: CPU start reason (Power on)
W (1714) LIBERTY: --> [Firmware] Liberty Device Software: (1.005)
W (1724) LIBERTY: --> [Firmware] Liberty Device Booted: (factory)
E (1734) LIBERTY: --> (factory) partition contains no data! (4354)
E (1734) LIBERTY: --> Cannot read factory partition!
I (1744) BTDM_INIT: BT controller compile version [67ee4f0]
I (1754) system_api: Base MAC address is not set
I (1754) system_api: read default base MAC address from EFUSE
I (1764) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (2164) BT_BTM: btm_sec_set_security_level : sec: 0x0

I (2164) BT_BTM: BTM_SEC_REG[0]: id 0, is_orig 0, psm 0x0001, proto_id 0, chan_id 0

I (2164) BT_BTM:                : sec: 0x80, service name [Service Discovery] (up to 21 chars saved)

I (2174) BT_BTM: btm_sec_set_security_level : sec: 0x0

I (2184) BT_BTM: BTM_SEC_REG[0]: id 0, is_orig 1, psm 0x0001, proto_id 0, chan_id 0

I (2184) BT_BTM:                : sec: 0x80, service name [Service Discovery] (up to 21 chars saved)

I (2194) BT_BTM: btm_sec_set_security_level : sec: 0x0

I (2204) BT_BTM: BTM_SEC_REG[1]: id 50, is_orig 1, psm 0x001f, proto_id 0, chan_id 0

I (2214) BT_BTM:                : sec: 0x80, service name [] (up to 21 chars saved)

I (2224) BT_BTM: btm_sec_set_security_level : sec: 0x0

I (2224) BT_BTM: BTM_SEC_REG[1]: id 50, is_orig 0, psm 0x001f, proto_id 0, chan_id 0

I (2234) BT_BTM:                : sec: 0x80, service name [] (up to 21 chars saved)

I (2304) BT_BTM: BTM_SetPinType: pin type 0 [variable-0, fixed-1], code , length 0

I (2304) BT_BTM: btm_sec_set_security_level : sec: 0x0

I (2304) BT_BTM: BTM_SEC_REG[2]: id 42, is_orig 0, psm 0x0003, proto_id 3, chan_id 0

I (2314) BT_BTM:                : sec: 0x80, service name [RFC_MUX
] (up to 21 chars saved)

I (2324) BT_BTM: BTM_SetInquiryMode

I (2324) BT_BTM: BTM_SetPageScanType

I (2334) BT_BTM: BTM_SetInquiryScanType

I (2344) BT_BTM: BTM_SecAddDevice, link key type:4

I (2344) BT_BTM: BTM_SecAddDevice, link key type:4

I (2354) BT_BTM: BTM_SecAddDevice, link key type:4

I (2354) BT_BTM: Write Extended Inquiry Response to controller

I (2364) BT_BTM: BTM_ReadDiscoverability

I (2364) BT_BTM: BTM_ReadConnectability

I (2374) BT_BTM: BTM_BleReadDiscoverability

I (2374) BT_BTM: BTM_BleReadConnectability

I (2384) BT_BTM: BTM_SetDiscoverability

I (2384) BT_BTM: BTM_SetDiscoverability: mode 2 [NonDisc-0, Lim-1, Gen-2], window 0x0012, interval 0x0800

I (2394) BT_BTM: BTM_SetConnectability

I (2404) BT_BTM: BTM_SetConnectability: mode 1 [NonConn-0, Conn-1], window 0x0012, interval 0x0800

W (2414) BT_BTC: A2DP Enable with AVRC
I (2414) BT_BTM: btm_sec_set_security_level : sec: 0x12

I (2424) BT_BTM: BTM_SEC_REG[3]: id 37, is_orig 1, psm 0x0019, proto_id 7, chan_id 0

I (2424) BT_BTM:                : sec: 0x2090, service name [] (up to 21 chars saved)

I (2434) BT_BTM: btm_sec_set_security_level : sec: 0x12

I (2444) BT_BTM: BTM_SEC_REG[3]: id 37, is_orig 0, psm 0x0019, proto_id 7, chan_id 0

I (2454) BT_BTM:                : sec: 0x3092, service name [] (up to 21 chars saved)

I (2464) BT_BTM: btm_sec_set_security_level : sec: 0x0

I (2464) BT_BTM: BTM_SEC_REG[4]: id 38, is_orig 1, psm 0x0019, proto_id 7, chan_id 1

I (2474) BT_BTM:                : sec: 0x80, service name [] (up to 21 chars saved)

I (2484) BT_BTM: btm_sec_set_security_level : sec: 0x0

I (2494) BT_BTM: BTM_SEC_REG[4]: id 38, is_orig 0, psm 0x0019, proto_id 7, chan_id 1

I (2494) BT_BTM:                : sec: 0x80, service name [] (up to 21 chars saved)

I (2504) BT_BTM: btm_sec_set_security_level : sec: 0x0

I (2514) BT_BTM: BTM_SEC_REG[4]: id 38, is_orig 1, psm 0x0019, proto_id 7, chan_id 2

I (2524) BT_BTM:                : sec: 0x80, service name [] (up to 21 chars saved)

I (2534) BT_BTM: btm_sec_set_security_level : sec: 0x0

I (2534) BT_BTM: BTM_SEC_REG[4]: id 38, is_orig 0, psm 0x0019, proto_id 7, chan_id 2

I (2544) BT_BTM:                : sec: 0x80, service name [] (up to 21 chars saved)

I (2554) BT_BTM: btm_sec_set_security_level : sec: 0x12

I (2554) BT_BTM: BTM_SEC_REG[5]: id 39, is_orig 1, psm 0x0017, proto_id 0, chan_id 0

I (2564) BT_BTM:                : sec: 0x2090, service name [] (up to 21 chars saved)

I (2574) BT_BTM: btm_sec_set_security_level : sec: 0x12

I (2584) BT_BTM: BTM_SEC_REG[5]: id 39, is_orig 0, psm 0x0017, proto_id 0, chan_id 0

I (2594) BT_BTM:                : sec: 0x3092, service name [] (up to 21 chars saved)

I (2594) BT_BTM: Write Extended Inquiry Response to controller

I (2604) BT_BTM: Write Extended Inquiry Response to controller

I (2614) BT_BTM: Write Extended Inquiry Response to controller

I (2624) BT_BTM: Write Extended Inquiry Response to controller

I (2624) BT_BTM: btm_sec_set_security_level : sec: 0x36

I (2634) BT_BTM: BTM_SEC_REG[6]: id 28, is_orig 0, psm 0x0003, proto_id 3, chan_id 1

I (2644) BT_BTM:                : sec: 0x1086, service name [] (up to 21 chars saved)

W (3154) LIBERTY: --> Bluetooth started OK
I (3154) LIBERTY: --> Have previously paired device: (8c:29:37:1e:86:34) autoconnect: (1)
I (3154) BT_L2CAP: L2CA_ErtmConnectReq()  PSM: 0x0001  BDA: 8c29371e8634  p_ertm_info: 0x0 allowed:0x0 preferred:0
I (3164) BT_BTM: BTM_InqDbRead: bd addr [8c29371e8634]

I (3174) BT_L2CAP: L2CAP - L2CA_conn_req(psm: 0x0001) returned CID: 0x0040
W (3814) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
I (3824) BT_BTM: BTM_InqDbRead: bd addr [8c29371e8634]

I (3834) BT_BTM: btm_sec_set_peer_sec_caps: sm4: 0x11, rmt_support_for_secure_connections 0

I (3834) BT_BTM: btm_process_remote_ext_features: pend:0

I (3844) BT_L2CAP: L2CA_SetDesireRole() new:x1, disallow_switch:0
I (3944) BT_L2CAP: L2CAP - Calling Connect_Cfm_Cb(), CID: 0x0040, Success
I (3944) BT_L2CAP: L2CA_ConfigReq()  CID 0x0040: fcr_present:0 (mode 0) mtu_present:1 (672)
I (3954) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0040
I (3954) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0040  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
I (3964) BT_L2CAP: L2CA_DataWrite()  CID: 0x0040  Len: 27
I (3974) BT_L2CAP: L2CA_DisconnectReq()  CID: 0x0040
I (3974) BT_BTM: BTM_SetPowerMode: pm_id 128 BDA: 371e8634 mode:0x0
I (4014) BT_L2CAP: L2CAP - Calling DisconnectCfm_Cb(), CID: 0x0040
I (4014) BT_BTM: btm_sec_set_security_level : sec: 0x36

I (4014) BT_BTM: BTM_SEC_REG[6]: id 28, is_orig 1, psm 0x0003, proto_id 3, chan_id 8

I (4024) BT_BTM:                : sec: 0x30b6, service name [] (up to 21 chars saved)

I (4034) BT_L2CAP: L2CA_ErtmConnectReq()  PSM: 0x0003  BDA: 8c29371e8634  p_ertm_info: 0x0 allowed:0x0 preferred:0
I (4044) BT_BTM: BTM_SetPowerMode: pm_id 128 BDA: 371e8634 mode:0x0
I (4054) BT_L2CAP: L2CAP - L2CA_conn_req(psm: 0x0003) returned CID: 0x0041
E (4304) BT_BTM: tBTM_SEC_DEV:0x3f80e338 rs_disc_pending=0

I (4314) BT_L2CAP: L2CAP - Calling Connect_Cfm_Cb(), CID: 0x0041, Success
I (4314) BT_L2CAP: L2CA_ConfigReq()  CID 0x0041: fcr_present:0 (mode 0) mtu_present:1 (1691)
W (4344) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
I (4344) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0041
I (4354) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0041  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
I (4364) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 4
I (4384) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 14
I (4394) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 4
I (4394) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 8
I (4404) BT_L2CAP: L2CA_SetDesireRole() new:x1, disallow_switch:0
W (4404) BT_APPL: new conn_srvc id:27, app_id:1
I (4404) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 8
E (4414) LIBERTY: APP HFP event: CONNECTION_STATE_EVT
E (4414) LIBERTY: --connection state connected, peer feats 0x0, chld_feats 0x0
W (4424) LIBERTY: HFP Connected
E (4434) LIBERTY: --> Not adding previously paired device...
I (4434) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 17
I (4454) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 16
I (4454) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 15
I (4464) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 14
I (4474) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 21
E (4474) LIBERTY: APP HFP event: NETWORK_STATE_EVT
E (4474) LIBERTY: --NETWORK STATE unavailable
I (4484) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 15
E (4484) LIBERTY: APP HFP event: CALL_IND_EVT
E (4494) LIBERTY: --Call indicator NO call in progress
E (4494) LIBERTY: APP HFP event: CALL_SETUP_IND_EVT
E (4504) LIBERTY: --Call setup indicator NONE
E (4504) LIBERTY: APP HFP event: BATTERY_LEVEL_IND_EVT
E (4514) LIBERTY: --battery level 4
I (4514) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 52
E (4524) LIBERTY: APP HFP event: SIGNAL_STRENGTH_IND_EVT
E (4534) LIBERTY: -- signal strength: 1
E (4534) LIBERTY: APP HFP event: ROAMING_STATUS_IND_EVT
E (4544) LIBERTY: --ROAMING: inactive
E (4544) LIBERTY: APP HFP event: CALL_HELD_IND_EVT
I (4554) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 15
E (4554) LIBERTY: --Call held indicator NONE held
E (4564) LIBERTY: APP HFP event: CONNECTION_STATE_EVT
E (4564) LIBERTY: --connection state slc_connected, peer feats 0x7ef, chld_feats 0x3f
E (4574) LIBERTY: APP HFP event: INBAND_RING_TONE_EVT
E (4584) LIBERTY: --inband ring state Provided
I (4584) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 15
W (4624) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
I (4624) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 14
I (4634) BT_L2CAP: L2CA_DataWrite()  CID: 0x0041  Len: 15
W (4674) BT_APPL: reset flags
I (4674) BT_L2CAP: L2CA_ErtmConnectReq()  PSM: 0x0001  BDA: 8c29371e8634  p_ertm_info: 0x0 allowed:0x0 preferred:0
I (4674) BT_BTM: BTM_SetPowerMode: pm_id 128 BDA: 371e8634 mode:0x0
I (4684) BT_L2CAP: L2CAP - L2CA_conn_req(psm: 0x0001) returned CID: 0x0040
E (4684) LIBERTY: --> Event? 0
I (4694) LIBERTY: A2DP connection state: Connecting, [8c:29:37:1e:86:34]
I (4694) BT_L2CAP: L2CAP - Calling Connect_Cfm_Cb(), CID: 0x0040, Success
I (4704) BT_L2CAP: L2CA_ConfigReq()  CID 0x0040: fcr_present:0 (mode 0) mtu_present:1 (672)
I (4774) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0040
I (4774) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0040  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
I (4784) BT_L2CAP: L2CA_DataWrite()  CID: 0x0040  Len: 24
I (4794) BT_L2CAP: L2CA_DisconnectReq()  CID: 0x0040
I (4794) BT_BTM: BTM_SetPowerMode: pm_id 128 BDA: 371e8634 mode:0x0
I (4844) BT_L2CAP: L2CAP - Calling DisconnectCfm_Cb(), CID: 0x0040
I (4844) BT_BTM: btm_sec_set_security_level : sec: 0x12

I (4844) BT_BTM: BTM_SEC_REG[3]: id 37, is_orig 1, psm 0x0019, proto_id 7, chan_id 0

I (4854) BT_BTM:                : sec: 0x3092, service name [] (up to 21 chars saved)

I (4864) BT_BTM: BTM_SetOutService p_out_serv id 37, psm 0x0019, proto_id 7, chan_id 0

I (4874) BT_L2CAP: L2CA_ErtmConnectReq()  PSM: 0x0019  BDA: 8c29371e8634  p_ertm_info: 0x0 allowed:0x0 preferred:0
I (4884) BT_BTM: BTM_SetPowerMode: pm_id 128 BDA: 371e8634 mode:0x0
I (4894) BT_L2CAP: L2CAP - L2CA_conn_req(psm: 0x0019) returned CID: 0x0042
I (4954) BT_L2CAP: L2CAP - Calling Connect_Cfm_Cb(), CID: 0x0042, Success
I (4954) BT_L2CAP: L2CA_ConfigReq()  CID 0x0042: fcr_present:0 (mode 0) mtu_present:1 (672)
I (5064) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0042  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
I (5064) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0042
I (5074) BT_L2CAP: L2CA_SetTxPriority()  CID: 0x0042, priority:0
I (5074) BT_L2CAP: L2CA_DataWrite()  CID: 0x0042  Len: 2
E (5084) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (5134) BT_L2CAP: L2CA_DataWrite()  CID: 0x0042  Len: 3
I (5144) BT_L2CAP: L2CA_DataWrite()  CID: 0x0042  Len: 3
I (5144) BT_L2CAP: L2CA_DataWrite()  CID: 0x0042  Len: 14
E (5144) LIBERTY: --> Event? 2
I (5144) LIBERTY: A2DP audio stream configuration, codec type 0
I (5154) BT_L2CAP: L2CA_DataWrite()  CID: 0x0042  Len: 3
I (5164) LIBERTY: Bluetooth configured, sample rate=44100
I (5254) BT_L2CAP: L2CA_ErtmConnectReq()  PSM: 0x0019  BDA: 8c29371e8634  p_ertm_info: 0x0 allowed:0x0 preferred:0
I (5254) BT_BTM: BTM_SetPowerMode: pm_id 128 BDA: 371e8634 mode:0x0
I (5264) BT_L2CAP: L2CAP - L2CA_conn_req(psm: 0x0019) returned CID: 0x0040
I (5294) BT_L2CAP: L2CAP - Calling Connect_Cfm_Cb(), CID: 0x0040, Success
I (5294) BT_L2CAP: L2CA_ConfigReq()  CID 0x0040: fcr_present:0 (mode 0) mtu_present:1 (1008)
I (5324) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0040
I (5324) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0040  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
I (5334) BT_L2CAP: L2CA_SetTxPriority()  CID: 0x0040, priority:1
I (5334) BT_L2CAP: L2CA_SetChnlFlushability()  CID: 0x0040  is_flushable: 1
I (5344) BT_L2CAP: L2CA_SetDesireRole() new:x1, disallow_switch:0
W (5354) BT_APPL: new conn_srvc id:19, app_id:0
E (5354) LIBERTY: --> Event? 0
I (5364) LIBERTY: A2DP connection state: Connected, [8c:29:37:1e:86:34]
I (5364) LIBERTY: A2DP connection state = CONNECTED
E (5374) LIBERTY: --> Not adding previously paired device...
I (5384) BT_L2CAP: L2CA_ErtmConnectReq()  PSM: 0x0001  BDA: 8c29371e8634  p_ertm_info: 0x0 allowed:0x0 preferred:0
I (5394) BT_BTM: BTM_SetPowerMode: pm_id 128 BDA: 371e8634 mode:0x0
I (5394) BT_L2CAP: L2CAP - L2CA_conn_req(psm: 0x0001) returned CID: 0x0043
I (5424) BT_L2CAP: L2CAP - Calling Connect_Cfm_Cb(), CID: 0x0043, Success
I (5424) BT_L2CAP: L2CA_ConfigReq()  CID 0x0043: fcr_present:0 (mode 0) mtu_present:1 (672)
I (5454) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0043
I (5454) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0043  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
I (5464) BT_L2CAP: L2CA_DataWrite()  CID: 0x0043  Len: 24
I (5474) BT_L2CAP: L2CA_DisconnectReq()  CID: 0x0043
I (5474) BT_BTM: BTM_SetPowerMode: pm_id 128 BDA: 371e8634 mode:0x0
I (5504) BT_L2CAP: L2CAP - Calling DisconnectCfm_Cb(), CID: 0x0043
I (5504) BT_BTM: BTM_SetOutService p_out_serv id 39, psm 0x0017, proto_id 0, chan_id 0

I (5514) BT_L2CAP: L2CA_ErtmConnectReq()  PSM: 0x0017  BDA: 8c29371e8634  p_ertm_info: 0x0 allowed:0x0 preferred:0
I (5524) BT_BTM: BTM_SetPowerMode: pm_id 128 BDA: 371e8634 mode:0x0
I (5534) BT_L2CAP: L2CAP - L2CA_conn_req(psm: 0x0017) returned CID: 0x0044
I (5544) BT_L2CAP: L2CAP - Calling Connect_Cfm_Cb(), CID: 0x0044, Success
I (5544) BT_L2CAP: L2CA_ConfigReq()  CID 0x0044: fcr_present:0 (mode 0) mtu_present:1 (512)
I (5574) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0044
I (5574) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0044  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
I (5584) BT_L2CAP: L2CA_SetTxPriority()  CID: 0x0044, priority:0
I (5594) BT_L2CAP: L2CA_DataWrite()  CID: 0x0044  Len: 15
I (5594) LIBERTY: --> Received AVRC Event: 0
I (5604) LIBERTY: ESP_AVRC_CT_CONNECTION_STATE_EVT
I (5604) LIBERTY: AVRC conn_state evt: state 1, [8c:29:37:1e:86:34]
I (5614) LIBERTY: --> Received AVRC Target Event: 0
I (5614) LIBERTY: --> Received AVRC Event: 5
I (5624) LIBERTY: AVRC remote features 25b
I (5624) LIBERTY: --> Received AVRC Target Event: 1

test_task       39      <1%
IDLE            2675231     57%
IDLE            4503926     96%
main            262564      5%
Tmr Svc         15      <1%
sys_evt         24      <1%
ipc1            153434      3%
esp_timer       265     <1%
hciT            61788       1%
BTU_TASK        873076      18%
BTC_TASK        181976      3%
btController    530823      11%
ipc0            76290       1%

Lock stats:
Name            Type            Arg    Active  
bt              APB_FREQ_MAX    0      1       
rtos1           CPU_FREQ_MAX    0      0       
rtos0           CPU_FREQ_MAX    0      1       
E (7714) LIBERTY: --> Connected to previously paired device: Kevin’s iPhone
E (7714) LIBERTY: --> Finished main!
I (8554) BT_BTM: BTM_SetPowerMode: pm_id 0 BDA: 371e8634 mode:0x2
W (8554) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
W (8584) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 800, status 0x0

test_task       38529       <1%
IDLE            5533401     71%
IDLE            7336422     95%
sys_evt         24      <1%
ipc1            153434      1%
hciT            62393       <1%
BTU_TASK        875593      11%
BTC_TASK        182242      2%
esp_timer       466     <1%
btController    681280      8%
ipc0            76290       <1%
Tmr Svc         15      <1%

Lock stats:
Name            Type            Arg    Active  
bt              APB_FREQ_MAX    0      0       
rtos1           CPU_FREQ_MAX    0      0       
rtos0           CPU_FREQ_MAX    0      1       

test_task       76962       <1%
IDLE            8521604     79%
IDLE            10110436        94%
ipc1            153434      1%
hciT            62393       <1%
BTU_TASK        875593      8%
BTC_TASK        182242      1%
ipc0            76290       <1%
esp_timer       725     <1%
btController    687626      6%
Tmr Svc         15      <1%
sys_evt         24      <1%

Lock stats:
Name            Type            Arg    Active  
bt              APB_FREQ_MAX    0      0       
rtos1           CPU_FREQ_MAX    0      0       
rtos0           CPU_FREQ_MAX    0      1       
W (12754) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0x0
I (12794) BT_L2CAP: L2CA_DataWrite()  CID: 0x0042  Len: 2
I (12794) BT_LOG: bta_av_link_role_ok hndl:x41 role:1 conn_audio:x1 bits:1 features:x824b

I (12794) BT_L2CAP: L2CA_SetDesireRole() new:x1, disallow_switch:0
W (12804) BT_APPL: new conn_srvc id:19, app_id:1
I (12804) BT_BTM: BTM_SetPowerMode: pm_id 0 BDA: 371e8634 mode:0x0
I (12814) BT_L2CAP: L2CA_SetAclPriority()  bdaddr: 8c29371e8634, priority:1
I (12824) BT_BTM: BTM_SetLinkPolicy hold not supported (settings: 0x0009)

I (12834) BT_BTM: BTM_SetLinkPolicy park not supported (settings: 0x0001)

I (12834) BT_BTM: BTM_SetPowerMode: pm_id 0 BDA: 371e8634 mode:0x0
E (12844) LIBERTY: --> Event? 1
I (12844) LIBERTY: A2DP audio state: Started
W (12854) LIBERTY: --> Hardware start
I (12854) gpio: GPIO[19]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
I (12884) gpio: GPIO[21]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (12884) ES8388_DRIVER: init,out:02, in:00
I (12894) AUDIO_HAL: Codec mode is 3, Ctrl:1
I (12894) LIBERTY: --> Starting
I (12894) LIBERTY: --> Stream (1) is in state (2), pipeline state (0), expects resume (0)
I (12904) LIBERTY: --> Stream (2) is in state (2), pipeline state (0), expects resume (0)
I (12914) LIBERTY: --> Stream (5) is in state (2), pipeline state (0), expects resume (0)
I (12924) LIBERTY: --> Stack item (0) is NULL
I (12924) LIBERTY: --> Stack item (1) is NULL
I (12934) LIBERTY: --> Stack item (2) is NULL
I (12934) LIBERTY: --> Stack item (3) is NULL
I (12944) LIBERTY: --> Stack item (4) is NULL
I (12944) LIBERTY: --> Started
I (12954) LIBERTY: --> Stream (1) is in state (2), pipeline state (0), expects resume (0)
I (12954) LIBERTY: --> Stream (2) is in state (2), pipeline state (0), expects resume (0)
I (12964) LIBERTY: --> Stream (5) is in state (2), pipeline state (0), expects resume (0)
I (12974) LIBERTY: --> Stack item (0), (2) is in state (2), pipeline state (0), expects resume (0)
I (12984) LIBERTY: --> Stack item (1) is NULL
I (12994) LIBERTY: --> Stack item (2) is NULL
I (12994) LIBERTY: --> Stack item (3) is NULL
I (13004) LIBERTY: --> Stack item (4) is NULL
W (13004) LIBERTY: --> A2DP Pipeline start... 44100
I (13014) I2S: APLL expected frequency is 22579200 Hz, real frequency is 22579193 Hz
I (13024) I2S: DMA Malloc info, datalen=blocksize=1200, dma_buf_count=3
I (13024) I2S: DMA Malloc info, datalen=blocksize=1200, dma_buf_count=3
I (13034) LYRAT_V4_3: I2S0, MCLK output by GPIO0
I (13044) AUDIO_PIPELINE: link el->rb, el:0x3f80e620, tag:a2dp_in_stream, rb:0x3f80e01c
I (13044) I2S: APLL expected frequency is 22579200 Hz, real frequency is 22579193 Hz
I (13054) AUDIO_ELEMENT: [a2dp_in_stream-0x3f80e620] Element task created
I (13064) AUDIO_ELEMENT: [i2s_stream_writer-0x3f80df40] Element task created
I (13074) AUDIO_PIPELINE: Func:audio_pipeline_run, Line:359, MEM Total:4212495 Bytes, Inter:125660 Bytes, Dram:114884 Bytes

I (13084) AUDIO_ELEMENT: [i2s_stream_writer] AEL_MSG_CMD_RESUME,state:1
I (13094) I2S_STREAM: AUDIO_STREAM_WRITER
I (13114) AUDIO_PIPELINE: Pipeline started

test_task       114390      <1%
IDLE            13623112        98%
IDLE            10516844        76%
Tmr Svc         15      <1%
esp_timer       801     <1%
ipc0            76468       <1%
hciT            112997      <1%
BTU_TASK        958637      6%
i2s_stream_writ 192933      1%
btController    897960      6%
BTC_TASK        644065      4%
sys_evt         24      <1%
ipc1            153434      1%

Lock stats:
Name            Type            Arg    Active  
i2s_driver      NO_LIGHT_SLEEP  0      1       
i2c_driver      APB_FREQ_MAX    0      0       
bt              APB_FREQ_MAX    0      1       
rtos1           CPU_FREQ_MAX    0      0       
rtos0           CPU_FREQ_MAX    0      1       
I (16474) BT_L2CAP: L2CA_DataWrite()  CID: 0x0042  Len: 2
I (16484) BT_L2CAP: L2CA_FlushChannel (FLUSH)  CID: 0x0040  NumToFlush: 65535  QC: 0  pFirst: 0x0
I (16484) BT_L2CAP: L2CA_SetAclPriority()  bdaddr: 8c29371e8634, priority:0
E (16564) LIBERTY: --> Event? 1
I (16564) LIBERTY: A2DP audio state: Suspended
I (16564) LIBERTY: --> Finished
I (16564) LIBERTY: --> Stream (1) is in state (2), pipeline state (0), expects resume (0)
I (16574) LIBERTY: --> Stream (2) is in state (2), pipeline state (2), expects resume (0)
I (16584) LIBERTY: --> Stream (5) is in state (2), pipeline state (0), expects resume (0)
I (16594) LIBERTY: --> Stack item (0), (2) is in state (2), pipeline state (2), expects resume (0)
I (16604) LIBERTY: --> Stack item (1) is NULL
I (16614) LIBERTY: --> Stack item (2) is NULL
I (16614) LIBERTY: --> Stack item (3) is NULL
I (16624) LIBERTY: --> Stack item (4) is NULL
E (16634) LIBERTY: --> BT pipeline stop, with states (0), (2)
W (16654) AUDIO_PIPELINE: There are no listener registered
I (16654) AUDIO_PIPELINE: audio_pipeline_unlinked
W (16654) AUDIO_ELEMENT: [a2dp_in_stream] Element has not create when AUDIO_ELEMENT_TERMINATE
W (16664) AUDIO_ELEMENT: [i2s_stream_writer] Element has not create when AUDIO_ELEMENT_TERMINATE
I (16674) I2S: DMA queue destroyed
I (16674) I2S: DMA queue destroyed
I (16684) LIBERTY: --> Finished pop
I (16684) LIBERTY: --> Stream (1) is in state (2), pipeline state (3), expects resume (0)
I (16694) LIBERTY: --> Stream (2) is in state (2), pipeline state (3), expects resume (0)
I (16704) LIBERTY: --> Stream (5) is in state (2), pipeline state (0), expects resume (0)
I (16714) LIBERTY: --> Stack item (0) is NULL
I (16714) LIBERTY: --> Stack item (1) is NULL
I (16724) LIBERTY: --> Stack item (2) is NULL
I (16724) LIBERTY: --> Stack item (3) is NULL
I (16734) LIBERTY: --> Stack item (4) is NULL
W (16734) LIBERTY: --> Hardware stop
I (16744) AUDIO_HAL: Codec mode is 3, Ctrl:0
I (16744) BT_L2CAP: L2CA_DataWrite()  CID: 0x0044  Len: 8
I (16754) BT_L2CAP: L2CA_DataWrite()  CID: 0x0044  Len: 8
I (16764) LIBERTY: --> Received AVRC Event: 1
I (16764) LIBERTY: AVRC passthrough rsp: key_code 0x45, key_state 0
I (16774) LIBERTY: --> Received AVRC Event: 1
I (16774) LIBERTY: AVRC passthrough rsp: key_code 0x45, key_state 1

test_task       150181      <1%
IDLE            12897988        76%
IDLE            16673114        99%
esp_timer       801     <1%
ipc0            76468       <1%
sys_evt         24      <1%
hciT            140899      <1%
BTU_TASK        994980      5%
BTC_TASK        953051      5%
btController    1071462     6%
ipc1            153434      <1%
Tmr Svc         15      <1%

Lock stats:
Name            Type            Arg    Active  
i2c_driver      APB_FREQ_MAX    0      0       
bt              APB_FREQ_MAX    0      1       
rtos1           CPU_FREQ_MAX    0      0       
rtos0           CPU_FREQ_MAX    0      1       
I (19684) BT_BTM: BTM_SetPowerMode: pm_id 0 BDA: 371e8634 mode:0x2
W (19684) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(30 54)
W (19714) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 54, status 0x0

test_task       191331      <1%
IDLE            15782429        79%
IDLE            19713114        99%
sys_evt         24      <1%
ipc1            153434      <1%
hciT            141451      <1%
BTU_TASK        997284      5%
BTC_TASK        953183      4%
esp_timer       2606        <1%
btController    1181078     5%
Tmr Svc         15      <1%
ipc0            76468       <1%

Lock stats:
Name            Type            Arg    Active  
i2c_driver      APB_FREQ_MAX    0      0       
bt              APB_FREQ_MAX    0      1       
rtos1           CPU_FREQ_MAX    0      0       
rtos0           CPU_FREQ_MAX    0      1       

test_task       233509      1%
IDLE            18687751        81%
IDLE            22753113        99%
ipc1            153434      <1%
hciT            141451      <1%
BTU_TASK        997284      4%
BTC_TASK        953183      4%
Tmr Svc         15      <1%
esp_timer       5755        <1%
btController    1270429     5%
ipc0            76468       <1%
sys_evt         24      <1%

Lock stats:
Name            Type            Arg    Active  
i2c_driver      APB_FREQ_MAX    0      0       
bt              APB_FREQ_MAX    0      1       
rtos1           CPU_FREQ_MAX    0      0       
rtos0           CPU_FREQ_MAX    0      1

More Information.

It appears that the connection does in fact go into SNIFF mode, but the following even is missing on iPhone, but is present on my S22+

W (33027) BT_HCI: hcif ssr evt: st 0x0, hdl 0x81, tx_lat 54 rx_lat 1188

[expresspotato]

So nearly 3 weeks without comment, the best I can do is attach an example of this and note that I have also see the following line missing on iPhone, but present on Android:

W (248283) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0

Seems like something is preventing the bt controller from returning to sniff mode.

The attached source is from a much larger project, with the majority taken out. It should be run on the LyraT v4.3 board and has IO22 (green LED) set to display when in / out of light sleep.

1. Build the project with idf.py build
2. Flash it
3. Reset the board
4. Pair with an Android phone and don't touch the screen for a few seconds (to avoid touch sounds being played)
5. Notice the ESP32 enters light sleep as expected
6. Play some music / youtube / etc
7. Notice the CPU is awake for the duration of the playback
8. Pause the source
9. Notice light sleep resumes
10. Reset the board
11. Pair with an iPhone
12. Repeat steps 5 - 9
13. Notice that light sleep doesn't resume until the device is disconnected

pipeline_a2dp_sink_and_hfp.zip

Light sleep is really important with our mass production project here as it is battery powered and plays audio from a device often.

[BetterJincheng]

@expresspotato Please test again with following menuconfig:

Component config -> FreeRTOS -> Tick rate (100 -> 1000)

Change the tick rate from 100 to 1000.

[expresspotato]

Hi @BetterJincheng thanks for the suggestion but it didn't make a difference...

Anyone from @espressif?

[AxelLin]

@expresspotato Please test again with following menuconfig:

Component config -> FreeRTOS -> Tick rate (100 -> 1000)

Change the tick rate from 100 to 1000.

@BetterJincheng What's the point of this change?

[expresspotato]

Hello anyone from Espressif (@espressif-bot),

This functionality is pretty critical for our application, and iPhone is a huge user base that's easy to target bug fixes for (since the OS behaves nearly identically across all generations of device).

The above example demonstrates the easy to reproduce problem. Is anyone able to take a look / comment?

[BetterJincheng]

@expresspotato We have tested the example examples/bluetooth/bluedroid/classic_bt/a2dp_sink at latest master branch using an ESP32. Nothing wrong with IOS devices on light sleep. You can have a try. Please let me know the test result and we will provide you with some support if needed.

Modify this in bt_app_av.c:

    /* when audio stream transmission state changed, this event comes */
    case ESP_A2D_AUDIO_STATE_EVT: {
        a2d = (esp_a2d_cb_param_t *)(p_param);
        ESP_LOGI(BT_AV_TAG, "A2DP audio state: %s", s_a2d_audio_state_str[a2d->audio_stat.state]);
        s_audio_state = a2d->audio_stat.state;
        if (ESP_A2D_AUDIO_STATE_STARTED == a2d->audio_stat.state) {
            s_pkt_cnt = 0;
        } else if (ESP_A2D_AUDIO_STATE_REMOTE_SUSPEND == a2d->audio_stat.state) {
            bt_i2s_driver_uninstall();
        }
        break;
    }

PS: ADD THIS: Component config -> FreeRTOS -> Tick rate (100 -> 1000)

[expresspotato]

Hello @BetterJincheng,

So using v4.4.3 there was no difference using the code above, as in my example zip attached above in this thread, the audio control (via pipline stop / terminate, audio_hal_ctrl_codec(..., AUDIO_HAL_CTRL_STOP), is already stopped when ESP_A2D_AUDIO_STATE_REMOTE_SUSPEND event comes.

Using v4.4.3 with the tick change, I can see that light sleep is possible, but it's not the same as on Android, the duty cycle is 9/10 vs Android's 1/10. This is unlikely to net any power savings when compared to Android. Something is preventing it from having a shorter duty cycle even though the ESP32 requests SNIFF mode.

The ESP32 receives the mode change:

Android: W (116346) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(30 54) W (116375) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 54, status 0x0

The key is the HCI SSR (Sniff Sub-Rating) event takes place. After this command the duty cycle returns to 10/100 on Android. W (116529) BT_HCI: hcif ssr evt: st 0x0, hdl 0x81, tx_lat 54 rx_lat 1188

Which is not seen on iOS: W (43321) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(30 54) W (43337) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 54, status 0x0 ...

Even though the mode change comes, no ssr event comes, and the duty cycle remains 9/10. I couldn't get this to compile on master, it seems ADF is not yet compatible with it yet, so the only version tested is v4.4.3.

Included is a video of this behaviour. 1) Board is reset, Android is connected. 2) Audio is played, audio is paused. 3) Light sleep resumes, connection remains.

4) Board is reset, iPhone is connected (doesn't seem to matter which, X, 11, 12, 5S) 5) Audio is played, audio is paused. 3) Light sleep is possible, but the duty cycle is very high, there is no HCI SSR event.

1:38 Video of Problem

[BetterJincheng]

@expresspotato ESP32 has requeseted for a sniff subrating of 22, but iPhone responded with a sniff subrating of 1. So ESP32 should wake to RX every 1*sniff_interval. It seems that the problem is not on the ESP32 side.

ESP32 lmp_sniff_subrating_req

iPhone lmp_sniff_subrating_res

Maybe you can increase the sniff interval to save power. However it will increase the latency. In file bta_api.h:

#define BTA_DM_PM_SNIFF4_MAX     54
#define BTA_DM_PM_SNIFF4_MIN     30

Maybe you can have a try.

#define BTA_DM_PM_SNIFF4_MAX     540
#define BTA_DM_PM_SNIFF4_MIN     300

[Alvin1Zhang]

Thanks for reporting, will close due to short of feedback, feel free to reopen with more updates. Thanks.

[expresspotato]

Thank you @BetterJincheng, @Alvin1Zhang, the change you suggested worked perfectly 👍