ESP32 SPP connection dropped after 3 seconds
Posted: Fri Jun 14, 2024 4:02 pm
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:
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:
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?
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
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)
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?