It looks to me as if the interaction between SerialBT and the BT stack is causing this issue. When I break up the large string in smaller chunks and send those chunks separately (waiting for SerialBT to finish using SerialBT.flush() in between the chunks), the problem goes away. Oddly enough I don't seem to loose any data. As messages arrive at their destination without loss of data.
Is this false alarm (and the congestion is handled internally to avoid loss of data) or should I be worried at my data will get corrupted at some point?
Sample output on serial monitor of the message in 1 piece:
Code: Select all
11:37:24.833 -> 391 - Command = {"CMD":"GET","GET":"ERRORS"}
11:37:24.833 -> 519 - GET command
11:37:24.833 -> 544 - Getting ERRORS
11:37:24.833 -> 88 - Responding to client
11:37:24.833 -> {
11:37:24.833 -> "RESULT": 200,
11:37:24.833 -> "ERRORS": {
11:37:24.833 -> "GENERAL_ERRORS": [
11:37:24.833 -> {
11:37:24.833 -> "NAME": "VBATT_LOW_VOLTAGE",
11:37:24.833 -> "VALUE": 1
11:37:24.833 -> },
11:37:24.833 -> {
11:37:24.833 -> "NAME": "BLUETOOTH_MESSAGE_BUFFER_OVERFLOW",
11:37:24.833 -> "VALUE": 2
11:37:24.833 -> },
11:37:24.833 -> {
11:37:24.833 -> "NAME": "BLUETOOTH_MESSAGE_TIME-OUT",
11:37:24.880 -> "VALUE": 3
11:37:24.880 -> },
11:37:24.880 -> {
11:37:24.880 -> "NAME": "JSON_NESTINGLIMIT_EXCEEDED",
11:37:24.880 -> "VALUE": 4
11:37:24.880 -> },
11:37:24.880 -> {
11:37:24.880 -> "NAME": "JSON_NESTING_MISMATCH",
11:37:24.880 -> "VALUE": 5
11:37:24.880 -> },
11:37:24.880 -> {
11:37:24.880 -> "NAME": "BUZZER_PLAYLIST_FULL",
11:37:24.880 -> "VALUE": 6
11:37:24.880 -> },
11:37:24.880 -> {
11:37:24.880 -> "NAME": "SYSTEM_ERROR",
11:37:24.880 -> "VALUE": 7
11:37:24.880 -> }
11:37:24.880 -> ],
11:37:24.880 -> "LOFLOAT_ERRORS": [
11:37:24.880 -> {
11:37:24.880 -> "NAME": "SENSOR_SIGNAL_ERROR",
11:37:24.880 -> "VALUE": 1
11:37:24.880 -> },
11:37:24.880 -> {
11:37:24.880 -> "NAME": "FLOAT_SENSOR_STUCK",
11:37:24.880 -> "VALUE": 2
11:37:24.880 -> },
11:37:24.927 -> {
11:37:24.927 -> "NAME": "FLOAT_SENSOR_STUCK_HIGH",
11:37:24.927 -> "VALUE": 3
11:37:24.927 -> },
11:37:24.927 -> {
11:37:24.927 -> "NAME": "FLOAT_SENSOR_STUCK_LOW",
11:37:24.927 -> "VALUE": 4
11:37:24.927 -> },
11:37:24.927 -> {
11:37:24.927 -> "NAME": "FLOAT_SENSOR_WIRE_FAULT",
11:37:24.927 -> "VALUE": 5
11:37:24.927 -> },
11:37:24.927 -> {
11:37:24.927 -> "NAME": "FLOAT_SENSOR_SHORT_GND",
11:37:24.927 -> "VALUE": 6
11:37:24.927 -> },
11:37:24.927 -> {
11:37:24.927 -> "NAME": "FLOAT_SENSOR_CONFLICT",
11:37:24.927 -> "VALUE": 7
11:37:24.927 -> },
11:37:24.927 -> {
11:37:24.927 -> "NAME": "FLOAT_SENSOR_OTHER_ERROR",
11:37:24.927 -> "VALUE": 8
11:37:24.927 -> }
11:37:24.927 -> ],
11:37:24.927 -> "HIFLOAT_ERRORS": [
11:37:24.974 -> {
11:37:24.974 -> "NAME": "SENSOR_SIGNAL_ERROR",
11:37:24.974 -> "VALUE": 1
11:37:24.974 -> },
11:37:24.974 -> {
11:37:24.974 -> "NAME": "FLOAT_SENSOR_STUCK",
11:37:24.974 -> "VALUE": 2
11:37:24.974 -> },
11:37:24.974 -> {
11:37:24.974 -> "NAME": "FLOAT_SENSOR_STUCK_HIGH",
11:37:24.974 -> "VALUE": 3
11:37:24.974 -> },
11:37:24.974 -> {
11:37:24.974 -> "NAME": "FLOAT_SENSOR_STUCK_LOW",
11:37:24.974 -> "VALUE": 4
11:37:24.974 -> },
11:37:24.974 -> {
11:37:24.974 -> "NAME": "FLOAT_SENSOR_WIRE_FAULT",
11:37:24.974 -> "VALUE": 5
11:37:24.974 -> },
11:37:24.974 -> {
11:37:24.974 -> "NAME": "FLOAT_SENSOR_SHORT_GND",
11:37:24.974 -> "VALUE": 6
11:37:24.974 -> },
11:37:24.974 -> {
11:37:24.974 -> "NAME": "FLOAT_SENSOR_CONFLICT",
11:37:25.021 -> "VALUE": 7
11:37:25.021 -> },
11:37:25.021 -> {
11:37:25.021 -> "NAME": "FLOAT_SENSOR_OTHER_ERROR",
11:37:25.021 -> "VALUE": 8
11:37:25.021 -> }
11:37:25.021 -> ],
11:37:25.021 -> "ZFES_FSH_ERRORS": [
11:37:25.021 -> {
11:37:25.021 -> "NAME": "ZFES_ERR_FSH_OTHER",
11:37:25.021 -> "VALUE": 1
11:37:25.021 -> },
11:37:25.021 -> {
11:37:25.021 -> "NAME": "ZFES_ERR_HEATER_OFF_TIMEOUT",
11:37:25.021 -> "VALUE": 2
11:37:25.021 -> }
11:37:25.021 -> ],
11:37:25.021 -> "ZFES_FSS_ERRORS": [
11:37:25.021 -> {
11:37:25.021 -> "NAME": "ZFES_ERR_FSS_OTHER",
11:37:25.021 -> "VALUE": 1
11:37:25.021 -> },
11:37:25.021 -> {
11:37:25.021 -> "NAME": "ZFES_ERR_DAC_NOT_RESPONDING",
11:37:25.021 -> "VALUE": 2
11:37:25.021 -> },
11:37:25.021 -> {
11:37:25.021 -> "NAME": "ZFES_ERR_DAC_BAD_VOLTAGE",
11:37:25.068 -> "VALUE": 3
11:37:25.068 -> }
11:37:25.068 -> ]
11:37:25.068 -> }
11:37:25.068 -> }
11:37:25.068 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.814 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.861 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.861 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.861 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.861 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.861 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.861 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.908 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.908 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.908 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.908 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.908 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.908 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.955 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed
11:37:25.955 -> 248 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changedCode: Select all
11:33:58.039 -> 391 - Command = {"CMD":"GET","GET":"ERRORS"}
11:33:58.039 -> 519 - GET command
11:33:58.039 -> 544 - Getting ERRORS
11:33:58.039 -> 88 - Responding to client
11:33:58.039 -> {
11:33:58.039 -> "RESULT": 200,
11:33:58.039 -> "ERRORS1": {
11:33:58.039 -> "GENERAL_ERRORS": [
11:33:58.039 -> {
11:33:58.039 -> "NAME": "VBATT_LOW_VOLTAGE",
11:33:58.039 -> "VALUE": 1
11:33:58.039 -> },
11:33:58.039 -> {
11:33:58.039 -> "NAME": "BLUETOOTH_MESSAGE_BUFFER_OVERFLOW",
11:33:58.039 -> "VALUE": 2
11:33:58.039 -> },
11:33:58.039 -> {
11:33:58.085 -> "NAME": "BLUETOOTH_MESSAGE_TIME-OUT",
11:33:58.085 -> "VALUE": 3
11:33:58.085 -> },
11:33:58.085 -> {
11:33:58.085 -> "NAME": "JSON_NESTINGLIMIT_EXCEEDED",
11:33:58.085 -> "VALUE": 4
11:33:58.085 -> },
11:33:58.085 -> {
11:33:58.085 -> "NAME": "JSON_NESTING_MISMATCH",
11:33:58.085 -> "VALUE": 5
11:33:58.085 -> },
11:33:58.085 -> {
11:33:58.085 -> "NAME": "BUZZER_PLAYLIST_FULL",
11:33:58.085 -> "VALUE": 6
11:33:58.085 -> },
11:33:58.085 -> {
11:33:58.085 -> "NAME": "SYSTEM_ERROR",
11:33:58.085 -> "VALUE": 7
11:33:58.085 -> }
11:33:58.085 -> ]
11:33:58.085 -> }
11:33:58.085 -> }
11:33:58.132 -> 88 - Responding to client
11:33:58.132 -> {
11:33:58.132 -> "RESULT": 200,
11:33:58.132 -> "ERRORS2": {
11:33:58.132 -> "LOFLOAT_ERRORS": [
11:33:58.132 -> {
11:33:58.132 -> "NAME": "SENSOR_SIGNAL_ERROR",
11:33:58.132 -> "VALUE": 1
11:33:58.132 -> },
11:33:58.132 -> {
11:33:58.132 -> "NAME": "FLOAT_SENSOR_STUCK",
11:33:58.132 -> "VALUE": 2
11:33:58.132 -> },
11:33:58.132 -> {
11:33:58.132 -> "NAME": "FLOAT_SENSOR_STUCK_HIGH",
11:33:58.132 -> "VALUE": 3
11:33:58.132 -> },
11:33:58.132 -> {
11:33:58.132 -> "NAME": "FLOAT_SENSOR_STUCK_LOW",
11:33:58.132 -> "VALUE": 4
11:33:58.132 -> },
11:33:58.132 -> {
11:33:58.132 -> "NAME": "FLOAT_SENSOR_WIRE_FAULT",
11:33:58.179 -> "VALUE": 5
11:33:58.179 -> },
11:33:58.179 -> {
11:33:58.179 -> "NAME": "FLOAT_SENSOR_SHORT_GND",
11:33:58.179 -> "VALUE": 6
11:33:58.179 -> },
11:33:58.179 -> {
11:33:58.179 -> "NAME": "FLOAT_SENSOR_CONFLICT",
11:33:58.179 -> "VALUE": 7
11:33:58.179 -> },
11:33:58.179 -> {
11:33:58.179 -> "NAME": "FLOAT_SENSOR_OTHER_ERROR",
11:33:58.179 -> "VALUE": 8
11:33:58.179 -> }
11:33:58.179 -> ]
11:33:58.179 -> }
11:33:58.179 -> }
11:33:58.179 -> 88 - Responding to client
11:33:58.179 -> {
11:33:58.179 -> "RESULT": 200,
11:33:58.179 -> "ERRORS3": {
11:33:58.179 -> "HIFLOAT_ERRORS": [
11:33:58.179 -> {
11:33:58.179 -> "NAME": "SENSOR_SIGNAL_ERROR",
11:33:58.179 -> "VALUE": 1
11:33:58.179 -> },
11:33:58.226 -> {
11:33:58.226 -> "NAME": "FLOAT_SENSOR_STUCK",
11:33:58.226 -> "VALUE": 2
11:33:58.226 -> },
11:33:58.226 -> {
11:33:58.226 -> "NAME": "FLOAT_SENSOR_STUCK_HIGH",
11:33:58.226 -> "VALUE": 3
11:33:58.226 -> },
11:33:58.226 -> {
11:33:58.226 -> "NAME": "FLOAT_SENSOR_STUCK_LOW",
11:33:58.226 -> "VALUE": 4
11:33:58.226 -> },
11:33:58.226 -> {
11:33:58.226 -> "NAME": "FLOAT_SENSOR_WIRE_FAULT",
11:33:58.226 -> "VALUE": 5
11:33:58.226 -> },
11:33:58.226 -> {
11:33:58.226 -> "NAME": "FLOAT_SENSOR_SHORT_GND",
11:33:58.226 -> "VALUE": 6
11:33:58.226 -> },
11:33:58.226 -> {
11:33:58.226 -> "NAME": "FLOAT_SENSOR_CONFLICT",
11:33:58.226 -> "VALUE": 7
11:33:58.226 -> },
11:33:58.226 -> {
11:33:58.226 -> "NAME": "FLOAT_SENSOR_OTHER_ERROR",
11:33:58.273 -> "VALUE": 8
11:33:58.273 -> }
11:33:58.273 -> ]
11:33:58.273 -> }
11:33:58.273 -> }
11:33:58.273 -> 88 - Responding to client
11:33:58.273 -> {
11:33:58.273 -> "RESULT": 200,
11:33:58.273 -> "ERRORS4": {
11:33:58.273 -> "ZFES_FSH_ERRORS": [
11:33:58.273 -> {
11:33:58.273 -> "NAME": "ZFES_ERR_FSH_OTHER",
11:33:58.273 -> "VALUE": 1
11:33:58.273 -> },
11:33:58.273 -> {
11:33:58.273 -> "NAME": "ZFES_ERR_HEATER_OFF_TIMEOUT",
11:33:58.273 -> "VALUE": 2
11:33:58.273 -> }
11:33:58.273 -> ]
11:33:58.273 -> }
11:33:58.273 -> }
11:33:58.273 -> 88 - Responding to client
11:33:58.273 -> {
11:33:58.273 -> "RESULT": 200,
11:33:58.273 -> "ERRORS5": {
11:33:58.273 -> "ZFES_FSS_ERRORS": [
11:33:58.273 -> {
11:33:58.273 -> "NAME": "ZFES_ERR_FSS_OTHER",
11:33:58.273 -> "VALUE": 1
11:33:58.320 -> },
11:33:58.320 -> {
11:33:58.320 -> "NAME": "ZFES_ERR_DAC_NOT_RESPONDING",
11:33:58.320 -> "VALUE": 2
11:33:58.320 -> },
11:33:58.320 -> {
11:33:58.320 -> "NAME": "ZFES_ERR_DAC_BAD_VOLTAGE",
11:33:58.320 -> "VALUE": 3
11:33:58.320 -> }
11:33:58.320 -> ]
11:33:58.320 -> }
11:33:58.320 -> }Code: Select all
void CMD_Respond2Client() {
#if VERBOSE
Serial.println("88 - Responding to client");
serializeJsonPretty(jsonDoc, Serial); // send to USB serial port
Serial.println(); // add empty line
#endif
responseSent = false; // set to "true" in BT ESP_SPP_WRITE_EVT
serializeJsonPretty(jsonDoc, SerialBT); // send to Bluetooth client
}Is it possible that the congestion occurs at the receiving end? How can I find out? Is there a rule or standard limiting how long a BT SPP message can be?
Edit:
Splitting the mesage in smaller chunks didn't help. When I was testing using the phone as BT client, ESP32 crashed. Inspection of the crash info revealed that using SerialBT.flush() appeared to interfere with the jsonDoc while BT transmission was ongoing. The Arduino ESP libs in Arduino 1.8.13 are outdated, so I fixed the SerialBT.flush() issue (#3579) manually in the library source file, but that didn't help. Back to square one.
Edit #2:
Expanded a bit on the congestion event and in all cases find that the congestion status is going back and forth between "FALSE" and "TRUE", while the status always is "ESP_SPP_SUCCESS". Since the status never goes to "ESP_SPP_FAILURE" can I asssume that it is safe to ignore this event (as long as the status remains "ESP_SPP_SUCCESS") ?
In that case, why am I seeing those events in the first place?
Code to analyze the event parameter:
Code: Select all
Serial.println("518 - ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed");
Serial.print("519 - Status = ");
switch(param->cong.status) {
case ESP_SPP_SUCCESS: // Successful operation
Serial.println("ESP_SPP_SUCCESS");
break;
case ESP_SPP_FAILURE: // Generic failure
Serial.println("ESP_SPP_FAILURE");
break;
case ESP_SPP_BUSY: // Temporarily can not handle this request
Serial.println("ESP_SPP_BUSY");
break;
case ESP_SPP_NO_DATA: // no data
Serial.println("ESP_SPP_NO_DATA");
break;
case ESP_SPP_NO_RESOURCE: // No more set pm control block
Serial.println("ESP_SPP_NO_RESOURCE");
break;
}
Serial.print("556 - Congestion = ");
if(param->cong.cong) Serial.println("TRUE");
else Serial.println("FALSE");
Edit #3
New experiment: added code to the ESP_SPP_WRITE_EVT event handler to count the number of bytes transmitted. Luckily, the event parameter also contained Congestion status information. Interesting observation: with the added code, which also sends information to the serial monitor, not a single congestion event happened and the congestion status in the WRITE event handler was always false.
When I comment the extra code out, the congestion events are back - but data is never lost in the transmission. I give up and just verify that all data are sent.
Code in the event callback:
Code: Select all
void BT_callback(esp_spp_cb_event_t event, esp_spp_cb_param_t * param) {
switch(event) {
... some other events...
case ESP_SPP_WRITE_EVT: // 33: SPP write operation completed, only for ESP_SPP_MODE_CB
On_ESP_SPP_WRITE(param); // handle the event
break;
...more events...
}
/****************************************************************************
* Bluetooth Event 33: SPP write operation completed *
****************************************************************************/
void On_ESP_SPP_WRITE(esp_spp_cb_param_t * param) {
#if VERBOSE
Serial.println("571 - ESP_SPP_WRITE_EVT: Bluetooth SPP write operation completed");
Serial.print("572 - Status = ");
switch(param->write.status) {
case ESP_SPP_SUCCESS: // Successful operation
Serial.println("ESP_SPP_SUCCESS");
break;
case ESP_SPP_FAILURE: // Generic failure
Serial.println("ESP_SPP_FAILURE");
break;
case ESP_SPP_BUSY: // Temporarily can not handle this request
Serial.println("ESP_SPP_BUSY");
break;
case ESP_SPP_NO_DATA: // no data
Serial.println("ESP_SPP_NO_DATA");
break;
case ESP_SPP_NO_RESOURCE: // No more set pm control block
Serial.println("ESP_SPP_NO_RESOURCE");
break;
}
Serial.print("595 - Bytes transmitted = ");
Serial.println(param->write.len, DEC);
sppTotalCharsSent += param->write.len;
Serial.print("598 - Total Bytes transmitted = ");
Serial.println(sppTotalCharsSent, DEC);
Serial.print("598 - Congestion = ");
if(param->write.cong) Serial.println("TRUE");
else Serial.println("FALSE");
#endif
}etc., etc.14:42:50.810 -> 571 - ESP_SPP_WRITE_EVT: Bluetooth SPP write operation completed
14:42:50.810 -> 572 - Status = ESP_SPP_SUCCESS
14:42:50.810 -> 595 - Bytes transmitted = 3
14:42:50.810 -> 598 - Total Bytes transmitted = 3
14:42:50.810 -> 598 - Congestion = FALSE
14:42:50.810 -> 571 - ESP_SPP_WRITE_EVT: Bluetooth SPP write operation completed
14:42:50.810 -> 572 - Status = ESP_SPP_SUCCESS
14:42:50.810 -> 595 - Bytes transmitted = 44
14:42:50.810 -> 598 - Total Bytes transmitted = 47
14:42:50.810 -> 598 - Congestion = FALSE
14:42:50.810 -> 571 - ESP_SPP_WRITE_EVT: Bluetooth SPP write operation completed
14:42:50.810 -> 572 - Status = ESP_SPP_SUCCESS
14:42:50.810 -> 595 - Bytes transmitted = 33
14:42:50.810 -> 598 - Total Bytes transmitted = 80
14:42:50.857 -> 598 - Congestion = FALSE
Data are sent in little chunks of mostly 30..40 bytes. Status is always ESP_SPP_SUCCESS and Congestion is always FALSE.
When I remove the call to On_ESP_SPP_WRITE(), the congestion events come back.