Silent playback after cold boot (rare)

tfabris commented 6 years ago

On extremely rare occasions, I encounter silent playback after a cold boot up on starting the car.

Note: This might be related to issue #70 - Perhaps it is the same root cause with a slightly different manifestation.

Avrcp works fully (track change commands, track titles, etc.), and everything is connected, but there is no audio coming out of the Honda stereo despite the fact that the empeg is playing songs and its volume is turned up.

I vaguely remember a situation once before where this happened when I was on the debug cable, and I think that, at the time, it did not help to issue a "streaming start" command to the Bluetooth chip at that time. Though I feel like I need to double check this. Will need to repro this with debug connected.

In the meantime, a power cycle of the Bluetooth will definitely fix it (long press on top button puts empeg to sleep which removes power from the Bluetooth chip which forces a reboot).

To try, if it repros:

Use the power button on my Honda car stereo to put the car stereo to sleep and then wake it up again. This does not reconnect Bluetooth; it stays connected when you do this. However if that fixes the problem, it might help narrow it down.
See if switching to a different input and back again, or engaging and disengaging Siri from the steering wheel, clears up the issue.
If you catch it with the debug cable connected, try issuing a Streaming Start command. And also save off the logs and look closely at the log to find out which part of the Bluetooth handshaking process got missed.

tfabris commented 6 years ago

CORRECTION: This is fixed by an "A2DP STREAMING START" command. I repro'd it on the debug cable and issued a streaming start command and it worked and the audio came back. Need to investigate places where I can better add streaming start commands.

Here is a debug output, note where you hand-issued streaming start. The audio worked after issuing the streaming start.

``` 0000001 Built in Arduino Serial has been started. 0000000 BlueGiga Serial has been started. 0000001 Empeg Serial has been started. 0000001 --^ Sending to empeg: W 0000001 BlueGigaEmpeg Version 1.0.96 0000003 Arduino chip type: AT Mega 2560 - Good. 0000005 Serial receive buffer size: 256 - Good. 0000004 Serial xmit buffer size: 128 - Good. 0000004 Pausing empeg for convenience while setting global chip defaults. 0000006 --^ Sending to empeg: W 0000002 Setting Defaults. 0000003 --^ SET CONTROL ESCAPE - 00 0 0000004 --^ SET CONTROL ECHO 5 0000002 --^ SET CONTROL BATTERY 0 0 0 0 0000004 --^ SET CONTROL CONFIG 0000 0000 0000 5100 0000005 --^ SET CONTROL CODEC 0000003 --^ SET CONTROL CODEC SBC JOINT_STEREO 44100 0 SET CONTROL CODEC APT-X_LL SET CONTROL CODEC APT-X SET CONTROL CODEC AAC 0000016 --^ SET BT CLASS 280428 0000001 --^ SET PROFILE SPP 0000002 --^ SET PROFILE A2DP SOURCE 0000003 --^ SET PROFILE AVRCP TARGET 1 0000003 --^ SET BT NAME empeg Car 0000003 --^ SET BT SSP 1 0 0000002 --^ SET BT AUTH * 0000 0000003 --^ SET CONTROL AUDIO INTERNAL I2S_SLAVE EVENT KEEPALIVE 16 0000007 --^ SET CONTROL PREAMP 0 0 0000003 --^ SET CONTROL MICBIAS 0 0 0000003 --^ SET CONTROL GAIN 9 0 0000002 Done Setting Defaults. 0000003 --^ Sending to empeg: W 0000002 Performing soft reset of Bluetooth module. 0000005 --^ RESET 0000001 Clearing global variables. 0002651 WRAP THOR AI (6.2.0 build 1122) 0000001 Clearing global variables. 0000002 Unable to send command to empeg, the empeg player application is not yet running: W 0000004 Copyright (c) 2003-2017 Silicon Labs Inc. 0000112 READY. 0007069 ------------------------------------- 0000001 empeg player application has started. 0000001 ------------------------------------- 0000000 Detected empeg bootup sequence completion, sending pause command to player. 0000007 --^ Sending to empeg: W 0000479 Pausing player on first timestamp after boot up. 0000001 --^ Sending to empeg: W 0008875 CONNECT 0 AVRCP 17 0000279 NO CARRIER 1 ERROR 9004 L2CAP_CONNECTION_REJ_RESOURCES 0000081 AVRCP 0 GET_CAPABILITIES 2 0000003 --^ AVRCP RSP 02FF 0000035 NO CARRIER 0 ERROR 0 0000003 --^ Sending to empeg: W 0000009 SYNTAX ERROR 0004059 CONNECT 0 AVRCP 17 0000141 AVRCP 0 GET_CAPABILITIES 2 0000002 --^ AVRCP RSP 02FF 0000079 AVRCP 0 LIST_APPLICATION_SETTING_ATTRIBUTES 0000004 --^ AVRCP RSP 3 0000059 NO CARRIER 1 ERROR 9004 L2CAP_CONNECTION_REJ_RESOURCES 0000039 NO CARRIER 0 ERROR 0 0000003 --^ Sending to empeg: W 0005340 CONNECT 0 AVRCP 17 0000274 NO CARRIER 1 ERROR 9004 L2CAP_CONNECTION_REJ_RESOURCES 0000103 AVRCP 0 GET_CAPABILITIES 2 0000002 --^ AVRCP RSP 02FF 0000037 NO CARRIER 0 ERROR 0 0000002 --^ Sending to empeg: W 0000008 SYNTAX ERROR 0004980 CONNECT 0 AVRCP 17 0000174 AVRCP 0 GET_CAPABILITIES 2 0000004 --^ AVRCP RSP 02FF 0000090 AVRCP 0 LIST_APPLICATION_SETTING_ATTRIBUTES 0000003 --^ AVRCP RSP 3 0000039 CONNECT 1 A2DP 19 0000178 CONNECT 2 A2DP 19 0000054 AVRCP 0 LIST_APPLICATION_SETTING_VALUES 3 0000004 --^ AVRCP RSP 1 2 0000069 AVRCP 0 GET_APPLICATION_SETTING_VALUE 01 03? 0000004 --^ AVRCP RSP 1 0000053 AVRCP 0 GET_CAPABILITIES 3 0000003 --^ AVRCP RSP 1 2 0000080 AVRCP 0 PDU_REGISTER_NOTIFICATION 5 PLAYBACK_STATUS_CHANGED 0 0000004 --^ AVRCP NFY INTERIM 5 1 2 0000082 AVRCP 0 PDU_REGISTER_NOTIFICATION 6 TRACK_CHANGED 0 0000004 --^ AVRCP NFY INTERIM 6 2 1 0000064 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 76000 2 0000065 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000004 --^ AVRCP RSP 1 1 "Scattering Seeds on the Pomegranate Tour" 0000107 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000003 --^ AVRCP RSP 1 2 "Mary Crowell" 0000106 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000005 --^ AVRCP RSP 1 3 "Scattering Seeds on the Pomegranate Tour" 0000102 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000004 --^ AVRCP RSP 1 4 "53" 0000091 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000004 --^ AVRCP RSP 1 5 "4474" 0000081 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000004 --^ AVRCP RSP 1 6 "Folk" 0000095 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000004 --^ AVRCP RSP 1 7 "76000" 0000080 AVRCP PLAY PRESS 0000003 --^ Sending to empeg: C 0000041 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000005 --^ AVRCP RSP 1 1 "Scattering Seeds on the Pomegranate Tour" 0000113 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000004 --^ AVRCP RSP 1 2 "Mary Crowell" 0000081 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000004 --^ AVRCP RSP 1 3 "Scattering Seeds on the Pomegranate Tour" 0000105 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000004 --^ AVRCP RSP 1 4 "53" 0000081 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000004 --^ AVRCP RSP 1 5 "4474" 0000027 --^ AVRCP NFY CHANGED 6 2 1 0000002 --^ AVRCP NFY CHANGED 5 1 1 0000002 Empeg state..................................PLAYING > 0000078 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000005 --^ AVRCP RSP 1 6 "Folk" 0000077 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000004 --^ AVRCP RSP 1 7 "76000" 0000077 AVRCP PLAY RELEASE 0000033 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 76000 1 0000079 AVRCP 0 PDU_REGISTER_NOTIFICATION 9 TRACK_CHANGED 0 0000005 --^ AVRCP NFY INTERIM 9 2 1 0000070 AVRCP 0 PDU_REGISTER_NOTIFICATION a PLAYBACK_STATUS_CHANGED 0 0000004 --^ AVRCP NFY INTERIM a 1 1 0000069 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000005 --^ AVRCP RSP 1 1 "Scattering Seeds on the Pomegranate Tour" 0000115 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000004 --^ AVRCP RSP 1 2 "Mary Crowell" 0000081 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000004 --^ AVRCP RSP 1 3 "Scattering Seeds on the Pomegranate Tour" 0000102 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000004 --^ AVRCP RSP 1 4 "53" 0000081 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000004 --^ AVRCP RSP 1 5 "4474" 0000083 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000004 --^ AVRCP RSP 1 6 "Folk" 0000084 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000004 --^ AVRCP RSP 1 7 "77000" 0000079 AVRCP PLAY PRESS 0000002 --^ Sending to empeg: C 0000046 AVRCP PLAY RELEASE 0000146 --^ AVRCP NFY CHANGED 9 2 1 0000005 Not sending PLAYBACK_STATUS_CHANGED notification with the PLAYING status because there is no state change, we already tried to send this data. 0000072 AVRCP 0 GET_PLAY_STATUS 0000002 --^ AVRCP RSP 297765 78000 1 0000095 AVRCP 0 PDU_REGISTER_NOTIFICATION 5 TRACK_CHANGED 0 0000004 --^ AVRCP NFY INTERIM 5 2 1 0000071 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000004 --^ AVRCP RSP 1 1 "Scattering Seeds on the Pomegranate Tour" 0000119 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000004 --^ AVRCP RSP 1 2 "Mary Crowell" 0000081 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000004 --^ AVRCP RSP 1 3 "Scattering Seeds on the Pomegranate Tour" 0000120 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000003 --^ AVRCP RSP 1 4 "53" 0000084 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000004 --^ AVRCP RSP 1 5 "4474" 0000072 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000003 --^ AVRCP RSP 1 6 "Folk" 0000084 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000004 --^ AVRCP RSP 1 7 "78000" 0000073 AVRCP PLAY PRESS 0000002 --^ Sending to empeg: C 0000033 AVRCP PLAY RELEASE 0000156 --^ AVRCP NFY CHANGED 5 2 1 0000003 Not sending PLAYBACK_STATUS_CHANGED notification with the PLAYING status because there is no state change, we already tried to send this data. 0000064 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 79000 1 0000066 AVRCP 0 PDU_REGISTER_NOTIFICATION 0 TRACK_CHANGED 0 0000004 --^ AVRCP NFY INTERIM 0 2 1 0000068 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000004 --^ AVRCP RSP 1 1 "Scattering Seeds on the Pomegranate Tour" 0000113 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000004 --^ AVRCP RSP 1 2 "Mary Crowell" 0000081 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000004 --^ AVRCP RSP 1 3 "Scattering Seeds on the Pomegranate Tour" 0000098 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000004 --^ AVRCP RSP 1 4 "53" 0000083 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000003 --^ AVRCP RSP 1 5 "4474" 0000094 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000004 --^ AVRCP RSP 1 6 "Folk" 0000080 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000003 --^ AVRCP RSP 1 7 "79000" 0015176 AVRCP FORWARD PRESS 0000003 --^ Sending to empeg: N 0000038 AVRCP FORWARD RELEASE 0000063 --^ AVRCP NFY CHANGED 0 2 1 0000054 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 273297 95000 1 0000065 AVRCP 0 PDU_REGISTER_NOTIFICATION b TRACK_CHANGED 0 0000006 --^ AVRCP NFY INTERIM b 2 1 0000072 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000004 --^ AVRCP RSP 1 1 "Rosario" 0000092 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000005 --^ AVRCP RSP 1 2 "Michael Gettel" 0000091 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000004 --^ AVRCP RSP 1 3 "San Juan Suite" 0000082 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000004 --^ AVRCP RSP 1 4 "54" 0000089 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000003 --^ AVRCP RSP 1 5 "4474" 0000103 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000005 --^ AVRCP RSP 1 6 "New Age" 0000092 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000003 --^ AVRCP RSP 1 7 "95000" 0001600 AVRCP BACKWARD PRESS 0000003 --^ Sending to empeg: P 0000041 AVRCP BACKWARD RELEASE 0001065 --^ AVRCP NFY CHANGED b 2 1 0000065 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 0 1 0000088 AVRCP 0 PDU_REGISTER_NOTIFICATION 6 TRACK_CHANGED 0 0000004 --^ AVRCP NFY INTERIM 6 2 1 0000067 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000004 --^ AVRCP RSP 1 1 "Scattering Seeds on the Pomegranate Tour" 0000124 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000003 --^ AVRCP RSP 1 2 "Mary Crowell" 0000093 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000004 --^ AVRCP RSP 1 3 "Scattering Seeds on the Pomegranate Tour" 0000112 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000004 --^ AVRCP RSP 1 4 "53" 0000071 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000003 --^ AVRCP RSP 1 5 "4474" 0000091 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000005 --^ AVRCP RSP 1 6 "Folk" 0000089 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000004 --^ AVRCP RSP 1 7 "1000" 0001753 AVRCP PAUSE PRESS 0000002 --^ Sending to empeg: W 0000035 AVRCP PAUSE RELEASE 0000073 --^ AVRCP NFY CHANGED a 1 2 0000001 Empeg state..................................PAUSED || 0000003 Not sending PLAYBACK_STATUS_CHANGED notification with the PAUSED status because there is no state change, we already tried to send this data. 0000079 AVRCP 0 PDU_REGISTER_NOTIFICATION 0 PLAYBACK_STATUS_CHANGED 0 0000004 --^ AVRCP NFY INTERIM 0 1 2 0001679 AVRCP PLAY PRESS 0000002 --^ Sending to empeg: C 0000034 AVRCP PLAY RELEASE 0000490 --^ AVRCP NFY CHANGED 6 2 1 0000003 --^ AVRCP NFY CHANGED 0 1 1 0000001 Empeg state..................................PLAYING > 0000066 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 4000 1 0000070 AVRCP 0 PDU_REGISTER_NOTIFICATION 4 TRACK_CHANGED 0 0000005 --^ AVRCP NFY INTERIM 4 2 1 0000071 AVRCP 0 PDU_REGISTER_NOTIFICATION 5 PLAYBACK_STATUS_CHANGED 0 0000004 --^ AVRCP NFY INTERIM 5 1 1 0000070 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000004 --^ AVRCP RSP 1 1 "Scattering Seeds on the Pomegranate Tour" 0000120 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000004 --^ AVRCP RSP 1 2 "Mary Crowell" 0000081 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000004 --^ AVRCP RSP 1 3 "Scattering Seeds on the Pomegranate Tour" 0000127 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000004 --^ AVRCP RSP 1 4 "53" 0000091 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000004 --^ AVRCP RSP 1 5 "4474" 0000081 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000004 --^ AVRCP RSP 1 6 "Folk" 0000100 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000004 --^ AVRCP RSP 1 7 "5000" 0000076 AVRCP PLAY PRESS 0000002 --^ Sending to empeg: C 0000028 AVRCP PLAY RELEASE 0000151 --^ AVRCP NFY CHANGED 4 2 1 0000005 Not sending PLAYBACK_STATUS_CHANGED notification with the PLAYING status because there is no state change, we already tried to send this data. 0000060 AVRCP 0 GET_PLAY_STATUS 0000002 --^ AVRCP RSP 297765 5000 1 0000072 AVRCP 0 PDU_REGISTER_NOTIFICATION 0 TRACK_CHANGED 0 0000005 --^ AVRCP NFY INTERIM 0 2 1 0000071 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000004 --^ AVRCP RSP 1 1 "Scattering Seeds on the Pomegranate Tour" 0000105 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000004 --^ AVRCP RSP 1 2 "Mary Crowell" 0000093 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000004 --^ AVRCP RSP 1 3 "Scattering Seeds on the Pomegranate Tour" 0000111 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000004 --^ AVRCP RSP 1 4 "53" 0000098 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000003 --^ AVRCP RSP 1 5 "4474" 0000082 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000004 --^ AVRCP RSP 1 6 "Folk" 0000084 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000004 --^ AVRCP RSP 1 7 "6000" 0000088 AVRCP PLAY PRESS 0000002 --^ Sending to empeg: C 0000044 AVRCP PLAY RELEASE 0000150 --^ AVRCP NFY CHANGED 0 2 1 0000005 Not sending PLAYBACK_STATUS_CHANGED notification with the PLAYING status because there is no state change, we already tried to send this data. 0000065 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 6000 1 0000070 AVRCP 0 PDU_REGISTER_NOTIFICATION b TRACK_CHANGED 0 0000004 --^ AVRCP NFY INTERIM b 2 1 0000074 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000004 --^ AVRCP RSP 1 1 "Scattering Seeds on the Pomegranate Tour" 0000124 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000004 --^ AVRCP RSP 1 2 "Mary Crowell" 0000096 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000004 --^ AVRCP RSP 1 3 "Scattering Seeds on the Pomegranate Tour" 0000109 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000004 --^ AVRCP RSP 1 4 "53" 0000077 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000004 --^ AVRCP RSP 1 5 "4474" 0000104 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000003 --^ AVRCP RSP 1 6 "Folk" 0000077 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000003 --^ AVRCP RSP 1 7 "7000" list 0007802 LIST 3 0000038 LIST 0 CONNECTED AVRCP 672 0 0 40 0 0 48:f0:7b:57:15:20 17 OUTGOING ACTIVE SLAVE ENCRYPTED 0 0000003 ------------------------------------ 0000001 AVRCP Channel is: 0000001 0 0000001 ------------------------------------ 0000025 LIST 1 CONNECTED A2DP 672 0 0 39 0 0 48:f0:7b:57:15:20 19 OUTGOING ACTIVE SLAVE ENCRYPTED 0 0000029 LIST 2 CONNECTED A2DP 672 0 0 39 0 0 48:f0:7b:57:15:20 19 OUTGOING ACTIVE SLAVE ENCRYPTED 0 a2dp streaming start 0010651 A2DP STREAMING START 1 0000002 --^ Sending to empeg: C 0000014 AUDIO ROUTE 1 A2DP LEFT RIGHT 0000003 --^ SET CONTROL RECONNECT 588 0 0 1f 0 NONE AVRCP A2DP 0000168 --^ AVRCP NFY CHANGED b 2 1 0000004 Not sending PLAYBACK_STATUS_CHANGED notification with the PLAYING status because there is no state change, we already tried to send this data. 0000533 A2DP CODEC SBC JOINT_STEREO 44100 BITPOOL 2-53 0000014 AVRCP 0 GET_PLAY_STATUS 0000002 --^ AVRCP RSP 297765 26000 1 0000072 AVRCP 0 PDU_REGISTER_NOTIFICATION 4 TRACK_CHANGED 0 0000005 --^ AVRCP NFY INTERIM 4 2 1 0000065 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000004 --^ AVRCP RSP 1 1 "Scattering Seeds on the Pomegranate Tour" 0000114 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000004 --^ AVRCP RSP 1 2 "Mary Crowell" 0000094 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000004 --^ AVRCP RSP 1 3 "Scattering Seeds on the Pomegranate Tour" 0000105 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000004 --^ AVRCP RSP 1 4 "53" 0000084 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000004 --^ AVRCP RSP 1 5 "4474" 0000084 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000003 --^ AVRCP RSP 1 6 "Folk" 0000079 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000004 --^ AVRCP RSP 1 7 "27000" 0000076 AVRCP 0 GET_PLAY_STATUS 0000002 --^ AVRCP RSP 297765 27000 1 0000470 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 27000 1 0000998 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 28000 1 0000997 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 29000 1 0000994 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 30000 1 0000999 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 31000 1 0000996 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 32000 1 0001005 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 33000 1 0001000 AVRCP 0 GET_PLAY_STATUS 0000004 --^ AVRCP RSP 297765 34000 1 0000996 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 35000 1 0000499 --^ AVRCP NFY CHANGED 5 1 2 0000001 Empeg state..................................PAUSED || 0000071 AVRCP 0 PDU_REGISTER_NOTIFICATION 6 PLAYBACK_STATUS_CHANGED 0 0000005 --^ AVRCP NFY INTERIM 6 1 2 0000424 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 36000 2 0000992 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 36000 2 0000999 AVRCP 0 GET_PLAY_STATUS 0000002 --^ AVRCP RSP 297765 36000 2 0000998 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 36000 2 0000998 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 36000 2 0000999 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 36000 2 0001001 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 36000 2 0000999 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 36000 2 0001003 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 36000 2 0000069 --^ AVRCP NFY CHANGED 4 2 1 0000005 --^ AVRCP NFY CHANGED 6 1 1 0000001 Empeg state..................................PLAYING > 0000074 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 36000 1 0000070 AVRCP 0 PDU_REGISTER_NOTIFICATION 1 TRACK_CHANGED 0 0000006 --^ AVRCP NFY INTERIM 1 2 1 0000073 AVRCP 0 PDU_REGISTER_NOTIFICATION 2 PLAYBACK_STATUS_CHANGED 0 0000005 --^ AVRCP NFY INTERIM 2 1 1 0000062 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 01? 0000004 --^ AVRCP RSP 1 1 "Scattering Seeds on the Pomegranate Tour" 0000125 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 02? 0000004 --^ AVRCP RSP 1 2 "Mary Crowell" 0000091 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 03? 0000003 --^ AVRCP RSP 1 3 "Scattering Seeds on the Pomegranate Tour" 0000128 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 04? 0000004 --^ AVRCP RSP 1 4 "53" 0000079 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 05? 0000004 --^ AVRCP RSP 1 5 "4474" 0000081 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 06? 0000003 --^ AVRCP RSP 1 6 "Folk" 0000082 AVRCP 0 GET_ELEMENT_ATTRIBUTES 01 07? 0000004 --^ AVRCP RSP 1 7 "37000" 0000071 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 37000 1 0000941 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 38000 1 0000998 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 39000 1 0000341 AVRCP PAUSE PRESS 0000002 --^ Sending to empeg: W 0000027 AVRCP PAUSE RELEASE 0000028 --^ AVRCP NFY CHANGED 2 1 2 0000002 Empeg state..................................PAUSED || 0000002 Not sending PLAYBACK_STATUS_CHANGED notification with the PAUSED status because there is no state change, we already tried to send this data. 0000075 AVRCP 0 PDU_REGISTER_NOTIFICATION f PLAYBACK_STATUS_CHANGED 0 0000004 --^ AVRCP NFY INTERIM f 1 2 0000516 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 39000 2 0001008 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 39000 2 0000996 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 39000 2 0000994 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 39000 2 0001008 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 39000 2 0000989 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 39000 2 0000999 AVRCP 0 GET_PLAY_STATUS 0000002 --^ AVRCP RSP 297765 39000 2 0001000 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 39000 2 0001005 AVRCP 0 GET_PLAY_STATUS 0000003 --^ AVRCP RSP 297765 39000 2 ```

tfabris commented 6 years ago

I have checked in a change which adds an "A2DP STREAMING START" command which I am hoping will fix this issue. The checkin is in version 1.0.96 in commit number 95bac912b5e978ff5a6ab6ba7a8c8fdee9439bb9 - I am not sure if this will fix it or not.

tfabris commented 6 years ago

I am closing this issue until I see it recur. I have high hopes for the fix from 1.0.96.

tfabris commented 6 years ago

The issue recurred, I have debug output from it, and the additional "A2DP STREAMING START" from 1.0.96 did not fix the issue.

Note: This issue is exceedingly rare now.

This is not the same thing as issue #70, I don't think, but here is an interesting similarity:

Good playback occurs when this message appears after connection: A2DP CODEC SBC JOINT_STEREO 44100 BITPOOL 2-53
Bad chipmunk playback (issue #70) occurs when this message appears with the wrong sample rate: A2DP CODEC SBC JOINT_STEREO 48000 BITPOOL 2-53
Silent playback (issue #67) occurs when NONE of those messages appear.

Also note:

The following message also does not appear at times when the issue is reproducing. AUDIO ROUTE 1 A2DP LEFT RIGHT

Interesting! Needs more research.

Note: The issue gets fixed if I hand-issue an "a2dp streaming start" command by hand much later. So somehwere this is fixable with a Streaming Start, just... not in the place where I put it originally.

Attached: Debug log output of the session.

Silent playback repro - Code based streaming start didn't work but issuing streaming start by hand later fixed it.txt

tfabris commented 6 years ago

Hm. Much like issue #70, this problem seems to occur when the Honda rings up the empeg, as opposed to the other way around. I see this interesting thing in the logs:

NO CARRIER 0 ERROR 9004 L2CAP_CONNECTION_REJ_RESOURCES NO CARRIER 0 ERROR 9004 L2CAP_CONNECTION_REJ_RESOURCES RING 1 48:f0:7b:57:15:20 19 A2DP --^ A2DP STREAMING START RING 0 48:f0:7b:57:15:20 17 AVRCP CONNECT 2 A2DP 19

So what I'm seeing here is that it rings the two channels out of order. It rings "1" first and then "0". It's possible that the problem occurs because I issue the streaming start command too soon, when only one of the A2DP channels is connected. Not sure.

To do: Investigate if there is a way to make the BlueGigaEmpeg to be "non discoverable" mode most of the time when it's trying to reconnect to things, for instance when it thinks it has a pairing buddy. Then depend entirely on the auto reconnect for the BGE to ring the host stereo, and not the other way around.

The trick is that we would want to put the BGE into discoverable mode for the sake of pairing. This might have to be done as part of the pairing process. Non-discoverable most of the time, then press pairing button to put into discoverable mode. But then what about the Honda that doesn't work in Inquriy mode? This might require looking at how to make the Honda work even when the BGE is in Inquriy mode. Hm. Maybe alternate chunks of inquiry mode, a few seconds on, a few seconds off, for example. See about that.

If we can fix this (make it so no one ever rings the BGE, it's always the other way around), then perhaps it will fix both this issue and also long-term root-cause fix issue #70.

tfabris commented 6 years ago

Investigating possible ways to make the device either discoverable or non-discoverable on command.

Look at SET BT LAP command.
- Section 6.56 in the main general iWrap command reference.

tfabris commented 6 years ago

The SET BT LAP command does interesting things, stuff that I'm experimenting with, but it does not solve this problem. I don't know how to keep a pre-paired device from ringing me first, other than to make sure that I'm the one that wins the race to do the calling.

tfabris commented 6 years ago

I think the ultimate solution would be to find out how to prevent other folks from ringing us up (a previously paired host stereo doing a successful RING command against us). Then we would depend entirely on our autoReconnect to initiate the reconnect. However I can't figure out how to do this. The SET BT LAP command does not work for this. So continue to test workarounds for this.

To do:

Try to test your theory that this is caused by a them-rings-you-up problem by turning off auto reconnect temporarily. Force the other guy to ring you up and see if the repro frequency goes up.
Try to find a later spot in the code for issuing an A2DP STREAMING START command and see if that fixes the issue.

tfabris commented 6 years ago

I got another repro on the debugger but it took a hella long time. I was using the disc/reco steps from the Honda front panel (trying to repro issue #70, using the most recent repro steps from that bug) and stumbled onto a repro. Issue #70 repros quite a bit more often than this one, this one is super extra rare.

Issuing an A2DP streaming start by hand didn't instantly fix it, but doing the A2dp streaming start a couple of times and then pressing some play pauses on the empeg front panel did get it working again.

Need to analyze the attached debug log in more detail.

To do:

Analyze the log and see why the streaming start didn't fix it right away and what other stuff I did that might have kicked the stream into working again.

Note: the repro is near the END of this log. Earlier in the log will be my attempts at reproing issue #70 and might in fact be some issue #70 repros in the log. You want to look towards the end to see the issue #67 repro.

Issue 67 Silent Playback - Another repro from disco-reco from Honda front panel.txt

tfabris commented 6 years ago

You had a theory that it was caused by a too-early "streaming start".

Currently experimenting:

Increase the lowest number where you perform an A2DP STREAMING START on either the RING or the CONNECT messages.
Instead of doing it on 1,2,3 just do it on 2,3.
See if that works on all test systems (I'm particularly concerned about Onkyo).
If it works on all of them, leave it in place and see if that gets rid of the problem.

tfabris commented 6 years ago

Tested the 2,3 instead of 1,2,3 fix so far on:

Honda
Kenwood
Plantronics
Etekcity

Still need to test on:

Onkyo
iHome

tfabris commented 6 years ago

Okay, can't do the "2,3" fix because that induces bug #70 (chipmunk).

I have found that if I issue Streaming Start too early, i.e., if you issue it on "0" or the "1" while the A2DP channels are still getting set up, then you get silence. GUESS: one of the A2DP channels is a data channel and the other is audio. If this first of the two A2DP channels that connects is the data channel, and you issue the Streaming Start too soon before the second one is set up, then you get no audio because you didn't issue the Streaming Start command after there was an audio channel to start.

Whereas there is some weird thing with the Honda where issuing streaming start too late causes the chipmunk bug. So that's a separate issue.

Working on some custom code now to hopefully handle this permanently. Stay tuned.

tfabris commented 6 years ago

Custom code which does intelligent triggering of the A2DP STREAMING START command only on the second A2DP message has been implemented in version 1.1.8, and is awaiting some more testing before final PR into Master branch.

tfabris commented 6 years ago

I believe this is fixed with version 1.1.8 with commit aa4714e16631d2e00532451237b136d01a93c956. Closing for now, can reopen if the issue recurs.

tfabris commented 6 years ago

Version 1.1.10, commit f2c327aff62d75fea7e1c0d55417f86586be0323, reverts the "streaming start" behavior back to pre-1.1.8 behavior, which is a "dumb" table that may occasionally induce this bug.

Re-opening this bug because it will still recur on rare occasions and I need to fully understand the correct timing with which to induce the Streaming Start command on all devices universally to avoid all possible issues.

tfabris commented 6 years ago

Idea:

If the issue is caused when the RINGs come out of order like this:

RING 1 48:f0:7b:57:15:20 19 A2DP --^ A2DP STREAMING START RING 0 48:f0:7b:57:15:20 17 AVRCP CONNECT 2 A2DP 19

... Then maybe what I need to do is simply wait for the second and third ones regardless of their number and regardless of whether they're AVRCP or A2DP and just issue the streaming starts in those cases.

This would end up behaving as sort of a hybrid between the "dumb" method and the prior failed attempt at the "smart" method.

That might possibly fix this without inducing additional repros of issue #70.

tfabris commented 6 years ago

No, I have a log of a second repro (above) where the RING commands came in in order and so I don't know the root cause of this one any more. Back to the drawing board.

tfabris commented 6 years ago

Attempting to have a conversation with Silicon Labs support as to when exactly the correct time is to issue the command "A2DP STREAMING START" because it seems to be the crux of the issue here. Their documentation does not say. The conversation is not going well, I'm basically asking "When" and they're answering "yes". So we might be stuck on this one.

Another idea is to try issuing the command later on as well, adding back in additional streaming starts in other logical places in the code. I had had a few of those in the past but removed them for various reasons. Consider finding a good spot or two to put some back and see if they can make things work without hurting stuff.

tfabris commented 6 years ago

Got a pretty good answer from tech support. Their answer was, essentially:

Issue the Streaming Start when you get the second A2DP connection.
If it doesn't work, issue it again later and see if that fixes it.

Though this is a good official answer, I am skeptical because I think this is what induced the 48k problem the most frequently. This is the behavior of the "intelligent" streaming start that I implemented earlier and my memory is telling me that this was the inducer of the 48k problem.

Need to do an experiment to be certain. But I think it's really like this in practice:

Issue streaming start after second and third RING or CONNECT (regardless of a2dp or avrcp):

     RING 0 48:f0:7b:57:15:20 19 A2DP
     RING 1 48:f0:7b:57:15:20 17 AVRCP
     --^ A2DP STREAMING START
     RING 2 48:f0:7b:57:15:20 19 A2DP
     --^ A2DP STREAMING START

... This seems to be good and rarely if ever induces either issue #67 or issue #70. I think the only reason I ever got issue #67 is becase I was triggering off of "RING 1" or "RING 2" or somesuch, and if the messages came out of order with RING 1 coming first, then I wasn't issuing the command on the second ring receipt and it induced #67. Not sure.

This works well on some devices but I think that this might intermittently induce the 48k problem on the Honda stereo:

     RING 0 48:f0:7b:57:15:20 19 A2DP
     RING 1 48:f0:7b:57:15:20 17 AVRCP
     RING 2 48:f0:7b:57:15:20 19 A2DP
     --^ A2DP STREAMING START

To do:

Return the code which did "only the second A2DP receipt gets a streaming start".
See if that induces or reduces the 48k issue #70.
If so, write code which issues a streaming start on the second and third receipt of any connect or ring command, regardless of the channel number and regardless of whether it's AVRCP or A2DP either way.
See if that makes things better and fixes issue #70 and/or induces or reduces the silent playback issue #67.

tfabris commented 6 years ago

I anticipate that this will be permanently fixed in the long term by the new streaming start behavior in 1.1.13. This is on a side branch at the moment but will be checked in when it's had more bake time on my test systems.

tfabris commented 6 years ago

This was extremely rare to begin with and I haven't had a repro since 1.1.13. Can close as soon as you merge 1.1.13 to master.

tfabris / BlueGigaEmpeg

Silent playback after cold boot (rare) #67