espressif / arduino-esp32

Arduino core for the ESP32
GNU Lesser General Public License v2.1
13.33k stars 7.36k forks source link

Regression issue with WiFiClientSecure (timeout related?) with large files #4666

Closed ambanmba closed 3 years ago

ambanmba commented 3 years ago

Hardware:

Board: ESP32 Dev Module Core Installation version: 1.0.5rc-4 IDE name: Arduino IDE Flash Frequency: 80Mhz PSRAM enabled: No Upload Speed: 921600 Computer OS: macOS 11 (Big Sur)

Description:

Needed to upgrade to 1.05.rc-4 to fix the Big Sur compatibility issue with esptool.py, but then Universal Telegram Bot started failing when sending larger (> 300K) images to Telegram. The debug trace showed the upload failing with debug messages below.

Reverting back to the version of WiFiClientSecure that came with 1.0.4 (dated 2-Oct-19) restores functionality and sending images no longer fails.

Sketch:

Refer the sendPhotoByBinary function here with photos that are > ~300k https://github.com/witnessmenow/Universal-Arduino-Telegram-Bot

Also refer sendPhotoByFile function here with > ~300k photos: https://github.com/cotestatnt/AsyncTelegram

Debug Messages:

[V][ssl_client.cpp:289] send_ssl_data(): Writing HTTP request with 0 bytes....
[V][ssl_client.cpp:293] send_ssl_data(): Handling error -26752
[V][ssl_client.cpp:36] _handle_error(): [send_ssl_data():294]: (-26752) SSL - Connection requires a write call
[V][ssl_client.cpp:259] stop_ssl_socket(): Cleaning SSL connection.
timkoers commented 3 years ago

I've got the same problem, not with the same code, but with PubSubClient. The issue is only present when I decrease the logging level to something that is not verbose. When I set the logging level to verbose (-DCORE_DEBUG_LEVEL=5), the issue is not here. So it's starting to look like a timing issue or something.

FBMinis commented 3 years ago

Hardware: Board: ESP32-Cam Core Installation version: 1.0.5rc-4 IDE name: Arduino IDE 1.8.5 Computer OS: Win10

Description:

My Arduino sketches that involved communication between the ESP-32Cam and Telegram stopped working once I began using dev 1.05.rc-6. They worked perfectly with 1.04 stable.

I noticed they were failing to connect with telegram api, so I tried adding client.setInsecure(); , whis is present in 1.05.rc-6 version of WifiClientSecure . This partially solved the problem: I was able to turn On a GPIO through Telegram but I couldnt retrieve a photo (it would never arrive even after 'done sending' message).

Reverting back to the version of WiFiClientSecure that came with 1.0.4 (dated 2-Oct-19) restores functionality and sending images no longer fails.

This worked as far as running the ESP32-Cam example in https://github.com/witnessmenow/Universal-Arduino-Telegram-Bot

This the the code from Universal Telegram Bot:

/*******************************************************************

   A Telegram bot for taking a photo with an ESP32Cam

   Parts used:
   ESP32-CAM module* - http://s.click.aliexpress.com/e/bnXR1eYs

    = Affiliate Links

   Note:
   - Make sure that you have either selected ESP32 Wrover Module,
           or another board which has PSRAM enabled
   - Choose "Huge App" partion scheme

   Some of the camera code comes from Rui Santos:
   https://randomnerdtutorials.com/esp32-cam-take-photo-save-microsd-card/

   Written by Brian Lough
    YouTube: https://www.youtube.com/brianlough
    Tindie: https://www.tindie.com/stores/brianlough/
    Twitter: https://twitter.com/witnessmenow
*******************************************************************/

// ----------------------------
// Standard Libraries - Already Installed if you have ESP32 set up
// ----------------------------

#include <WiFi.h>
#include <WiFiClientSecure.h>
#include <UniversalTelegramBot.h>
#include "esp_camera.h"
#include <ArduinoJson.h>
//#include "camera_pins.h"
//#include "camera_code.h"

//define CAMERA_MODEL_AI_THINKER
#define PWDN_GPIO_NUM 32
#define RESET_GPIO_NUM -1
#define XCLK_GPIO_NUM 0
#define SIOD_GPIO_NUM 26
#define SIOC_GPIO_NUM 27
#define Y9_GPIO_NUM 35
#define Y8_GPIO_NUM 34
#define Y7_GPIO_NUM 39
#define Y6_GPIO_NUM 36
#define Y5_GPIO_NUM 21
#define Y4_GPIO_NUM 19
#define Y3_GPIO_NUM 18
#define Y2_GPIO_NUM 5
#define VSYNC_GPIO_NUM 25
#define HREF_GPIO_NUM 23
#define PCLK_GPIO_NUM 22

// Wifi network station credentials
#define WIFI_SSID "YOURSSID"
#define WIFI_PASSWORD "YOURPASSWORD"
// Telegram BOT Token (Get from Botfather)
#define BOT_TOKEN "YOURTOKEN"

#define FLASH_LED_PIN 4

const unsigned long BOT_MTBS = 1000; // mean time between scan messages

unsigned long bot_lasttime; // last time messages' scan has been done
WiFiClientSecure secured_client;
UniversalTelegramBot bot(BOT_TOKEN, secured_client);

bool flashState = LOW;

camera_fb_t *fb = NULL;

bool isMoreDataAvailable();
byte *getNextBuffer();
int getNextBufferLen();

bool dataAvailable = false;

void handleNewMessages(int numNewMessages)
{
  Serial.println("handleNewMessages");
  Serial.println(String(numNewMessages));

  for (int i = 0; i < numNewMessages; i++)
  {
    String chat_id = String(bot.messages[i].chat_id);
    String text = bot.messages[i].text;

    String from_name = bot.messages[i].from_name;
    if (from_name == "")
      from_name = "Guest";

    if (text == "/flash")
    {
      flashState = !flashState;
      digitalWrite(FLASH_LED_PIN, flashState);
    }

    if (text == "/photo")
    {
      fb = NULL;
      // Take Picture with Camera
      fb = esp_camera_fb_get();
      if (!fb)
      {
        Serial.println("Camera capture failed");
        bot.sendMessage(chat_id, "Camera capture failed", "");
        return;
      }
      dataAvailable = true;
      Serial.println("Sending");
      bot.sendPhotoByBinary(chat_id, "image/jpeg", fb->len,
                            isMoreDataAvailable, nullptr,
                            getNextBuffer, getNextBufferLen);

      Serial.println("done!");

      esp_camera_fb_return(fb);
    }

    if (text == "/start")
    {
      String welcome = "Welcome to the ESP32Cam Telegram bot.\n\n";
      welcome += "/photo : will take a photo\n";
      welcome += "/flash : toggle flash LED (VERY BRIGHT!)\n";
      bot.sendMessage(chat_id, welcome, "Markdown");
    }
  }
}

bool isMoreDataAvailable()
{
  if (dataAvailable)
  {
    dataAvailable = false;
    return true;
  }
  else
  {
    return false;
  }
}

byte *getNextBuffer()
{
  if (fb)
  {
    return fb->buf;
  }
  else
  {
    return nullptr;
  }
}

int getNextBufferLen()
{
  if (fb)
  {
    return fb->len;
  }
  else
  {
    return 0;
  }
}

void setup()
{
  Serial.begin(115200);
  Serial.println();

  pinMode(FLASH_LED_PIN, OUTPUT);
  digitalWrite(FLASH_LED_PIN, flashState); //defaults to low
  camera_config_t config;
  config.ledc_channel = LEDC_CHANNEL_0;
  config.ledc_timer = LEDC_TIMER_0;
  config.pin_d0 = Y2_GPIO_NUM;
  config.pin_d1 = Y3_GPIO_NUM;
  config.pin_d2 = Y4_GPIO_NUM;
  config.pin_d3 = Y5_GPIO_NUM;
  config.pin_d4 = Y6_GPIO_NUM;
  config.pin_d5 = Y7_GPIO_NUM;
  config.pin_d6 = Y8_GPIO_NUM;
  config.pin_d7 = Y9_GPIO_NUM;
  config.pin_xclk = XCLK_GPIO_NUM;
  config.pin_pclk = PCLK_GPIO_NUM;
  config.pin_vsync = VSYNC_GPIO_NUM;
  config.pin_href = HREF_GPIO_NUM;
  config.pin_sscb_sda = SIOD_GPIO_NUM;
  config.pin_sscb_scl = SIOC_GPIO_NUM;
  config.pin_pwdn = PWDN_GPIO_NUM;
  config.pin_reset = RESET_GPIO_NUM;
  config.xclk_freq_hz = 20000000;
  config.pixel_format = PIXFORMAT_JPEG;
  //init with high specs to pre-allocate larger buffers
  if (psramFound())
  {
    config.frame_size = FRAMESIZE_UXGA; // FRAMESIZE_ + QVGA|CIF|VGA|SVGA|XGA|SXGA|UXGA
    config.jpeg_quality = 10;
    config.fb_count = 2;
  }
  else
  {
    config.frame_size = FRAMESIZE_SVGA;
    config.jpeg_quality = 12;
    config.fb_count = 1;
  }

#if defined(CAMERA_MODEL_ESP_EYE)
  pinMode(13, INPUT_PULLUP);
  pinMode(14, INPUT_PULLUP);
#endif

  // camera init
  esp_err_t err = esp_camera_init(&config);
  if (err != ESP_OK)
  {
    Serial.printf("Camera init failed with error 0x%x", err);
  }

  sensor_t *s = esp_camera_sensor_get();
  //initial sensors are flipped vertically and colors are a bit saturated
  if (s->id.PID == OV3660_PID)
  {
    s->set_vflip(s, 1);       //flip it back
    s->set_brightness(s, 1);  //up the blightness just a bit
    s->set_saturation(s, -2); //lower the saturation
  }
  //drop down frame size for higher initial frame rate
  s->set_framesize(s, FRAMESIZE_QVGA);

#if defined(CAMERA_MODEL_M5STACK_WIDE)
  s->set_vflip(s, 1);
  s->set_hmirror(s, 1);
#endif

  // attempt to connect to Wifi network:
  Serial.print("Connecting to Wifi SSID ");
  Serial.print(WIFI_SSID);
  WiFi.begin(WIFI_SSID, WIFI_PASSWORD);
  secured_client.setCACert(TELEGRAM_CERTIFICATE_ROOT); // Add root certificate for api.telegram.org
  while (WiFi.status() != WL_CONNECTED)
  {
    Serial.print(".");
    delay(500);
  }
  Serial.print("\nWiFi connected. IP address: ");
  Serial.println(WiFi.localIP());

  Serial.print("Retrieving time: ");
  configTime(0, 0, "pool.ntp.org"); // get UTC time via NTP
  time_t now = time(nullptr);
  while (now < 24 * 3600)
  {
    Serial.print(".");
    delay(100);
    now = time(nullptr);
  }
  Serial.println(now);

  // Make the bot wait for a new message for up to 60seconds
  bot.longPoll = 60;
}

void loop()
{
  if (millis() - bot_lasttime > BOT_MTBS)
  {
    int numNewMessages = bot.getUpdates(bot.last_message_received + 1);

    while (numNewMessages)
    {
      Serial.println("got response");
      handleNewMessages(numNewMessages);
      numNewMessages = bot.getUpdates(bot.last_message_received + 1);
    }

    bot_lasttime = millis();
  }
}
johnwalicki commented 3 years ago

My ESP32 is also reporting this error with WiFiClientSecure and PubSubClient sending MQTT data.
[ssl_client.cpp:36] _handle_error(): [send_ssl_data():294]: (-26752) SSL - Connection requires a write call

With the recent version of ssl_client.cpp, it works for small buffers, but fails on larger buffers. Prior version of ssl_client.cpp works with all the buffers sizes I give it.

The regression seems to be in the ssl_client.cpp int send_ssl_data() function. The while() loop works, the if() fails.

$ diff ssl_client.cpp.prior ssl_client.cpp.latest
293,296c293,297
<     while ((ret = mbedtls_ssl_write(&ssl_client->ssl_ctx, data, len)) <= 0) {
<         if (ret != MBEDTLS_ERR_SSL_WANT_READ && ret != MBEDTLS_ERR_SSL_WANT_WRITE) {
<             return handle_error(ret);
<         }
---
>     if ((ret = mbedtls_ssl_write(&ssl_client->ssl_ctx, data, len)) <= 0){
>         log_v("Handling error %d", ret); //for low level debug
>         return handle_error(ret);
>     } else{
>         log_v("Returning with %d bytes written", ret); //for low level debug
456a458
> 
johnwalicki commented 3 years ago

Seems to fixed in this commit https://github.com/espressif/arduino-esp32/commit/560c0f45f58b907f0d699f65408b87fe54650854#diff-1294bfb831e132940639f2b2768d1444395a9d982ff45c2e7b4b5f73e4e99d6f

jameszah commented 3 years ago

This might be the same issue with mbedtls_ssl_write() -- not necessarily a bug, but different behavior.

client->println(F("")); which used to work, needs to be changed to: client->println();

Its purpose was to send another cr-lf (2 bytes), but what it was actually doing was sending a 0 byte message, then the 2 byte message, but ssl_client.cpp, which calls mbedtls_ssl_write(), declared a fatal error after the 0 byte message.

19:06:57.685 -> *[V][ssl_client.cpp:295] send_ssl_data(): Writing HTTP request with 0 bytes... 19:06:59.279 -> [V][ssl_client.cpp:300] send_ssl_data(): Handling error -80 19:06:59.279 -> [E][ssl_client.cpp:36] _handle_error(): [send_ssl_data():301]: (-80) UNKNOWN ERROR CODE (0050) 19:06:59.279 -> [V][ssl_client.cpp:265] stop_ssl_socket(): Cleaning SSL connection. 19:06:59.314 -> **Start request: --------------------------b8f610217e83e29b

https://github.com/witnessmenow/Universal-Arduino-Telegram-Bot/issues/235#issue-842397567

stale[bot] commented 3 years ago

[STALE_SET] This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 14 days if no further activity occurs. Thank you for your contributions.

stale[bot] commented 3 years ago

[STALE_DEL] This stale issue has been automatically closed. Thank you for your contributions.