ESP32 Forum

ESP32 Official Forum
http://esp32.io/

ESP_SPP_CONG_EVT when sending large amount of data using BT classic

http://esp32.io/viewtopic.php?f=19&t=18811

Page 1 of 1

ESP_SPP_CONG_EVT when sending large amount of data using BT classic

Posted: Sat Jan 02, 2021 11:04 am
by Gilbert
My application generates strings in JSON format (using ArduinoJSON) and sends them to Bluetooth Serial Terminal on my PC for testing. In real life, the BT Serial connection will be made with an Android phone, but the outcome is the same (tested using Serial Bluetooth Terminal). When the string is fairly small, there seems to be no problem. As the strings grow bigger, I start to see "ESP_SPP_CONG_EVT: Bluetooth SPP connection congestion status changed" notifications. The bigger the string, the more notifications I'm seeing.
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 changed
Sample output of the same message broken up in 5 pieces:

Code: 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 -> }
The congestion notifications appear after the message in the serial monitor, because I first send the data to the serial monitor and then to Serial BT. See code:

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
}
The maximum size of jsonDoc is 2kB. But I assume that only the part which is used by the message is passed to SeriaBT.
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");
Remark: the espressif documentation describes a few more status enums, but they are not defined in the header file which comes with ESP Arduino support package version 1.0.4 (latest stable release).

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
}
Output to serial monitor (partly):
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
etc., etc.
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.
All times are UTC
Page 1 of 1
Powered by phpBB® Forum Software © phpBB Limited
https://www.phpbb.com/