ESP32 SPP connection dropped after 3 seconds

[InfiniteArray]

This is about the same issue I describe in my other thread What do the acl_disconn_cmpl_stat error codes mean?. However, this is no longer about the meaning of the error codes, which is why I decided to split it out.

This might be the same issue as reported by chucrut back in 2023 in their post: Bluetooth connection lost after pairing

Observed behavior: Trying to establish a SPP connection with Bluetooth Classic fails on an ESP32-WROOM-32E. The pairing is successful, but after 2-5 seconds the remote host terminates the connection. During the brief time that the pairing is "successful" no ESP_SPP_SRV_OPEN_EVT is ever fired. Once the connection has been lost, the pairing needs to be forgotten again before another attempt at pairing can be made. This behavior has been observed using the BluetoothSerial library's SerialToSerialBT example, written by Evandro Copercini as well as the bt_spp_acceptor example from the ESP-IDF. The behavior was observed both with a Quest 3, a Quest 2, 2 different Windows 11 PCs and 2 different ESP32-WROOM-32E modules. Interestingly, the issue has not been observed on a Samsung Galaxy S9 with the Serial Bluetooth App.

Expected behavior: I'd expect the SPP examples to establish a Bluetooth Classic SPP connection that does not terminate.

Info:
One thing I found out early is that the type of connection might play a role. Installing the A2DP_sink example did not lead to a dropped connection. I gathered data from the ESP32 itself in verbose mode, connecting to the chip both with my phone and with a Windows 11 machine:

Code: Select all

[129883][I][BluetoothSerial.cpp:605] esp_bt_gap_cb(): ESP_BT_GAP_ACL_CONN_CMPL_STAT_EVT ACL connection complete status event
[130202][I][BluetoothSerial.cpp:380] esp_spp_cb(): ESP_SPP_SRV_OPEN_EVT: 0
[131148][I][BluetoothSerial.cpp:310] esp_spp_cb(): ESP_SPP_CLOSE_EVT status:0 handle:129 close_by_remote:1 attempt 0
[135276][I][BluetoothSerial.cpp:609] esp_bt_gap_cb(): ESP_BT_GAP_ACL_DISCONN_CMPL_STAT_EVT ACL disconnection complete status event: reason 278, handle 128
[688667][I][BluetoothSerial.cpp:605] esp_bt_gap_cb(): ESP_BT_GAP_ACL_CONN_CMPL_STAT_EVT ACL connection complete status event
[689278][V][BluetoothSerial.cpp:520] esp_bt_gap_cb(): authentication success: DESKTOP-ANH57SL
[692457][I][BluetoothSerial.cpp:609] esp_bt_gap_cb(): ESP_BT_GAP_ACL_DISCONN_CMPL_STAT_EVT ACL disconnection complete status event: reason 275, handle 128

The first connection was made with my phone. Second one with my Windows 11 machine. The first "ACL disconnection complete" came after I voluntarily closed the connection on my phone. The second "ACL disconnection complete" came unprompted after about 3 seconds.

I then captured a WireShark capture of a failing connection:

Code: Select all

120	7.251010	controller	host	HCI_EVT	29	Rcvd LE Meta (LE Extended Advertising Report)
121	7.252017	controller	host	HCI_EVT	60	Rcvd LE Meta (LE Extended Advertising Report)
122	7.252642	host	controller	HCI_CMD	4	Sent Inquiry Cancel
123	7.254977	controller	host	HCI_EVT	7	Rcvd Command Complete (Inquiry Cancel)
124	7.255007	host	controller	HCI_CMD	10	Sent LE Set Extended Scan Enable
125	7.281029	controller	host	HCI_EVT	60	Rcvd LE Meta (LE Extended Advertising Report)
126	7.281983	controller	host	HCI_EVT	7	Rcvd Command Complete (LE Set Extended Scan Enable)
127	7.281998	host	controller	HCI_CMD	17	Sent Create Connection
128	7.284979	controller	host	HCI_EVT	7	Rcvd Command Status (Create Connection)
129	7.284985	host	controller	HCI_CMD	6	Sent Vendor Command 0x001E (opcode 0xFC1E)
130	7.287984	controller	host	HCI_EVT	8	Rcvd Command Complete (Vendor Command 0x001E [opcode 0xFC1E])
131	7.288013	host	controller	HCI_CMD	12	Sent LE Set Extended Scan Parameters
132	7.290974	controller	host	HCI_EVT	7	Rcvd Command Complete (LE Set Extended Scan Parameters)
133	7.291000	host	controller	HCI_CMD	10	Sent LE Set Extended Scan Enable
134	7.293976	controller	host	HCI_EVT	7	Rcvd Command Complete (LE Set Extended Scan Enable)
135	7.924017	controller	host	HCI_EVT	14	Rcvd Connect Complete
136	7.924045	host	controller	HCI_CMD	6	Sent Read RSSI
137	7.925021	controller	host	HCI_EVT	36	Rcvd Vendor-Specific
138	7.926993	controller	host	HCI_EVT	10	Rcvd Command Complete (Read RSSI)
139	7.928984	controller	host	HCI_EVT	6	Rcvd Max Slots Change
140	7.929809	localhost ()	Espressif_0d:93:16 (ESP32-BT-Follower)	L2CAP	17	Sent Connection Request (SDP, SCID: 0x0040)
141	7.929836	host	controller	HCI_CMD	6	Sent Role Discovery
142	7.930301	Espressif_0d:93:16 (ESP32-BT-Follower)	localhost ()	L2CAP	15	Rcvd Information Request (Extended Features Mask)
143	7.930311	localhost ()	Espressif_0d:93:16 (ESP32-BT-Follower)	L2CAP	21	Sent Information Response (Extended Features Mask, Success)
144	7.931976	controller	host	HCI_EVT	10	Rcvd Command Complete (Role Discovery)
145	7.931984	host	controller	HCI_CMD	8	Sent Write Automatic Flush Timeout
146	7.932968	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
147	7.934974	controller	host	HCI_EVT	9	Rcvd Command Complete (Write Automatic Flush Timeout)
148	7.934981	host	controller	HCI_CMD	6	Sent Read Clock offset
149	7.936627	Espressif_0d:93:16 (ESP32-BT-Follower)	localhost ()	L2CAP	21	Rcvd Connection Response - Pending (SCID: 0x0040)
150	7.937972	controller	host	HCI_EVT	7	Rcvd Command Status (Read Clock offset)
151	7.937980	host	controller	HCI_CMD	7	Sent Read Tx Power Level
152	7.938968	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
153	7.940976	controller	host	HCI_EVT	10	Rcvd Command Complete (Read Tx Power Level)
154	7.940983	host	controller	HCI_CMD	6	Sent Read Link Quality
155	7.941541	Espressif_0d:93:16 (ESP32-BT-Follower)	localhost ()	L2CAP	15	Rcvd Information Request (Fixed Channels Supported)
156	7.941549	localhost ()	Espressif_0d:93:16 (ESP32-BT-Follower)	L2CAP	25	Sent Information Response (Fixed Channels Supported, Success)
157	7.942968	controller	host	HCI_EVT	8	Rcvd Read Clock Offset Complete
158	7.943968	controller	host	HCI_EVT	10	Rcvd Command Complete (Read Link Quality)
159	7.943974	host	controller	HCI_CMD	6	Sent Read Link Supervision Timeout
160	7.944971	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
161	7.946970	controller	host	HCI_EVT	11	Rcvd Command Complete (Read Link Supervision Timeout)
162	7.946983	host	controller	HCI_CMD	7	Sent Read Tx Power Level
163	7.947864	Espressif_0d:93:16 (ESP32-BT-Follower)	localhost ()	L2CAP	21	Rcvd Connection Response - Success (SCID: 0x0040, DCID: 0x0041)
164	7.947873	localhost ()	Espressif_0d:93:16 (ESP32-BT-Follower)	L2CAP	21	Sent Configure Request (DCID: 0x0041)
165	7.949127	Espressif_0d:93:16 (ESP32-BT-Follower)	localhost ()	L2CAP	21	Rcvd Configure Request (DCID: 0x0040)
166	7.949133	localhost ()	Espressif_0d:93:16 (ESP32-BT-Follower)	L2CAP	19	Sent Configure Response - Success (SCID: 0x0041)
167	7.949973	controller	host	HCI_EVT	10	Rcvd Command Complete (Read Tx Power Level)
168	7.970987	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
169	7.971978	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
170	7.975346	Espressif_0d:93:16 (ESP32-BT-Follower)	localhost ()	L2CAP	19	Rcvd Configure Response - Success (SCID: 0x0040)
171	7.976348	host	controller	HCI_CMD	6	Sent Authentication Requested
172	7.978978	controller	host	HCI_EVT	7	Rcvd Command Status (Authentication Requested)
173	7.979971	controller	host	HCI_EVT	9	Rcvd Link Key Request
174	7.979985	host	controller	HCI_CMD	10	Sent Link Key Request Negative Reply
175	7.982976	controller	host	HCI_EVT	13	Rcvd Command Complete (Link Key Request Negative Reply)
176	7.983969	controller	host	HCI_EVT	9	Rcvd IO Capability Request
177	7.983982	host	controller	HCI_CMD	13	Sent IO Capability Request Reply
178	7.986979	controller	host	HCI_EVT	13	Rcvd Command Complete (IO Capability Request Reply)
179	7.991980	controller	host	HCI_EVT	12	Rcvd IO Capability Response
180	8.208992	controller	host	HCI_EVT	13	Rcvd User Confirmation Request
181	8.272548	host	controller	HCI_CMD	10	Sent User Confirmation Request Reply
182	8.274989	controller	host	HCI_EVT	13	Rcvd Command Complete (User Confirmation Request Reply)
183	8.285978	controller	host	HCI_EVT	10	Rcvd Simple Pairing Complete
184	8.343053	controller	host	HCI_EVT	3	Rcvd Link Key Notification[Malformed Packet]
185	8.343772	host	controller	HCI_CMD	7	Sent Set Connection Encryption
186	8.344329	controller	host	HCI_EVT	6	Rcvd Authentication Complete
187	8.345979	controller	host	HCI_EVT	7	Rcvd Command Status (Set Connection Encryption)
188	8.347600	localhost ()	Espressif_0d:93:16 (ESP32-BT-Follower)	SDP	29	Sent Service Search Attribute Request : L2CAP: Attribute Range (0x0000 - 0xffff) 
189	8.448012	controller	host	HCI_EVT	7	Rcvd Encryption Change
190	8.454994	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
191	8.456830	Espressif_0d:93:16 (ESP32-BT-Follower)	localhost ()	SDP	90	Rcvd Service Search Attribute Response 
192	8.458410	localhost ()	Espressif_0d:93:16 (ESP32-BT-Follower)	SDP	29	Sent Service Search Attribute Request : PnP Information: Attribute Range (0x0201 - 0x0205) 
193	8.461976	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
194	8.464103	Espressif_0d:93:16 (ESP32-BT-Follower)	localhost ()	SDP	19	Rcvd Service Search Attribute Response 
195	8.467918	localhost ()	Espressif_0d:93:16 (ESP32-BT-Follower)	L2CAP	17	Sent Disconnection Request (SCID: 0x0040, DCID: 0x0041, PSM: 0x0001, Service: SDP)
196	8.471999	controller	host	HCI_EVT	8	Rcvd Number of Completed Packets
197	8.474092	Espressif_0d:93:16 (ESP32-BT-Follower)	localhost ()	L2CAP	17	Rcvd Disconnection Response (SCID: 0x0040, DCID: 0x0041, PSM: 0x0001, Service: SDP)
198	11.466791	host	controller	HCI_CMD	7	Sent Disconnect
199	11.534481	controller	host	HCI_EVT	7	Rcvd Command Status (Disconnect)
200	11.620997	controller	host	HCI_EVT	7	Rcvd Disconnect Complete
201	11.622025	controller	host	HCI_EVT	53	Rcvd Vendor-Specific
202	12.782239	controller	host	HCI_EVT	29	Rcvd LE Meta (LE Extended Advertising Report)
203	14.212467	controller	host	HCI_EVT	29	Rcvd LE Meta (LE Extended Advertising Report)

To me, the capture looks like everything is going well. The ESP32 responds to all requests and then the host asks to disconnect at 8.4679s.

I am hoping that someone with a bit more understanding of Bluetooth might understand why the remote host could be asking for this connection to be terminated?

[InfiniteArray]

I figured it out. The reason was entirely unrelated to the ESP32 or SPP.

The reason I initially thought the Bluetooth Connection was being terminated was because the BluetoothHelper class I was using on the Oculus 3 was returning a "BlueToothNotReadyException" when I tried connecting to the ESP32 devkit. "BlueToothNotReadyException" meaning that "the Bluetooth device is not paired" according to the class definition.

Every time I paired the ESP32 with the Quest 3 I saw the device show up with the connected devices for a few seconds, then get moved to the not connected devices after 3 seconds. And anytime I ran my script it would tell me that the device wasn't paired, despite me pairing and re-pairing the ESP32 over and over. So I thought this must had something to do with the device getting moved to the not-connected pile.

So, the actual problem: In order to quickly iterate the code on the Quest 3 I was running the program over the Meta Quest Link. This means that the code was actually compiled and run on my PC's hardware, and the Quest 3 provided the monitors and sensors. Most notably: My Bluetooth code was not using the Quest's Bluetooth hardware, but my PCs. I had only paired the ESP32 with the Quest 3, but I actually had to pair the ESP32 with the PC. When pairing, the device would still move to the not connected pile after three seconds but my script was then able to connect to it later on.

[tanmanh0707]

Since you already figured it out, I'm here to ask for your help. Could you show me how to configure Wireshark to capture Bluetooth packages? I'm using Bluetooth classic, can it be captured? Thank you.

[InfiniteArray]

Hi tanmath, yes it can be captured. I followed the instructions in this Stackoverflow answer.

I'll copy them here in case the link ever goes bad:

To capture Bluetooth traffic using Wireshark you will need the BTP software package, you can get it here. Install the package and find the files (usually it will install in C:\BTP[version]). Find a file named btvs.exe in folder x86. Launch a console with the admin privileges and type

./btvs.exe -Mode Wireshark

Wireshark windows will launch and start capturing traffic immediately.

- comath

I found that, in order to start another capture I had to restart the service from the console.

Keep in mind: This will only capture Bluetooth traffic between your PC and the remote device. To capture all the Bluetooth packets, even those not involving your PC you will need another tool. The OP on Stackoverflow bought Ubertooth for that. I have no experience with that software.

[tanmanh0707]

Hi tanmath, yes it can be captured. I followed the instructions in this Stackoverflow answer.

I'll copy them here in case the link ever goes bad:

To capture Bluetooth traffic using Wireshark you will need the BTP software package, you can get it here. Install the package and find the files (usually it will install in C:\BTP[version]). Find a file named btvs.exe in folder x86. Launch a console with the admin privileges and type

./btvs.exe -Mode Wireshark

Wireshark windows will launch and start capturing traffic immediately.

- comath

I found that, in order to start another capture I had to restart the service from the console.

Keep in mind: This will only capture Bluetooth traffic between your PC and the remote device. To capture all the Bluetooth packets, even those not involving your PC you will need another tool. The OP on Stackoverflow bought Ubertooth for that. I have no experience with that software.

Thank you very much for your kind help.