Timeout in client_net_recv_timeout forces unneeded delays?

[Bascy]

We are downloading a firmware binary file (2Mb) from a google cloud bucket using https.
When we set the timeout of SSLClient to 1000ms (to prevent timeouts when using slower servers) some calls to client_net_recv_timeout wait at least the 1000ms before continuing to read the available data. If we set the timeout to 10ms the whole process will go much faster because it won't wait for 1000 ms every time. See screenshots below.

It looks like the amount that is returned by client->available() is not correct somehow, which will cause the wait for the timeout to expire before the read is executed, and the full number of expected bytes is read.

Any idea what is going wrong here?

With timeout of 1000ms

With timeout of 10ms

[RobertByrnes]

int client_net_recv_timeout(void *ctx, unsigned char *buf, size_t len, uint32_t timeout) {
  Client *client = (Client*)ctx;

  if (!client) { 
    log_e("Uninitialised!");
    return -1;
  }

  if (len == 0) {
    log_e("Zero length specified!");
    return 0;
  }

  log_v("Timeout set to %u", timeout);

  unsigned long start = millis();
  unsigned long tms = start + timeout;
  
  int pending = client->available();
  while (pending < len && millis() < tms) {
    delay(1);
    pending = client->available();
  }
  
  int result = client->read(buf, len);
  
  if (!result) {
    return MBEDTLS_ERR_SSL_WANT_READ;
  }

  log_v("SSL client RX (received=%d expected=%zu in %lums)", result, len, millis()-start);
  
  if (result > 0) {
    //esp_log_buffer_hexdump_internal("SSL.RD", buf, (uint16_t)result, ESP_LOG_VERBOSE);
  }
  
  return result;
}

Please try this instead

[Bascy]

Timeout 10ms: error (probably because it takes more than 10 ms from line 114 to 118)

Timeout: 1000ms: the same timing issues

I also added some logging in the while loop (timeout 1000ms):

[Bascy]

@RobertByrnes Do you have any ideas on this?

[RobertByrnes]

@Bascy apologies but I haven't had an opportunity to look further at this and I won't for at least the next week. Just a thought though - if client->available() you think may not be returning the correct number of bytes available, maybe look here:

/**
 * \brief             Check if there is data to read or not.
 * 
 * \param ssl_client  sslclient_context* - The ssl client context. 
 * \return int        The number of bytes to read. 
 */
int data_to_read(sslclient_context *ssl_client) {
  int ret, res;
  
  ret = mbedtls_ssl_read(&ssl_client->ssl_ctx, NULL, 0);
  log_d("RET: %i",ret);   // for low level debug
  
  res = mbedtls_ssl_get_bytes_avail(&ssl_client->ssl_ctx);
  log_d("RES: %i",res);    // for low level debug
  
  if (ret != MBEDTLS_ERR_SSL_WANT_READ && ret != MBEDTLS_ERR_SSL_WANT_WRITE && ret < 0) {
    return handle_error(ret);
  }

  return res;
}

[Bascy]

@RobertByrnes
Hi Robert, its been some time but I'm wondering if you might have had time to look at this issue....

[RobertByrnes]

Hi @Bascy I have just had a look the code which handles the available() method and the call to it, I cannot see an issue. Please will you update to the latest version of this library and try again, if the issue persists please post (a sanitised version of) your main code file.

[Bascy]

I did not mention yet that we are using an EthernetClient as the underlying client in this setup, from https://github.com/arduino-libraries/Ethernet.git. It looks like EthernetClass::socketRecvAvailable() in socket.cpp is not updating the reported available bytes when called multiple times, so the timeout loop in client_net_recv_timeout() will always wait untill the timeout expires.

I tried it with the following modifications, and now its running like a racecar :)

uint16_t EthernetClass::socketRecvAvailable(uint8_t s)
{
  uint16_t ret = state[s].RX_RSR;
  // if (ret == 0) {       <== commented out
  SPI.beginTransaction(SPI_ETHERNET_SETTINGS);
  uint16_t rsr = getSnRX_RSR(s);
  SPI.endTransaction();
  ret = rsr - state[s].RX_inc;
  state[s].RX_RSR = ret;
  // }
  return ret;
}

[RobertByrnes]

@Bascy Ah I see, it's a complicated stack though ain't it with the transport layer, client, ssl and other libraries in the mix!

Are you saying that with the change to the Ethernet lib, the bytes available is being reported correctly so the SSLClient works well?

If that's the case then I think a first step to put a debug level log line in this client when the timeout is reached that this can be caused by the underlying client. Could be worth raising an issue or PR with the Ethernet lib aswell so that it reports the availability correctly....

[RobertByrnes]

@Bascy Maybe also this might be a change to test out:

This brings back the do while loop which executes slightly different to the while loop in the later versions. Also, this use vTaskDelay() so as to be none blocking (even though the delay is only for 1 millisecond!). This also has the logging. Fancy trying it? This code is in this branch: 59-timeout-in-client_net_recv_timeout-forces-unneeded-delays

int client_net_recv_timeout(void *ctx, unsigned char *buf, size_t len, uint32_t timeout) {
  Client *client = (Client*)ctx;

  if (!client) { 
    log_e("Uninitialised!");
    return -1;
  }

  if (len == 0) {
    log_e("Zero length specified!");
    return 0;
  }

  log_v("Timeout set to %u", timeout);

  unsigned long start = millis();
  unsigned long tms = start + timeout;
  
  do {
    int pending = client->available();
    if (pending < len && timeout > 0) {
      vTaskDelay(pdMS_TO_TICKS(1));
    } else {
      break;
    }
  } while (millis() < tms);

  if(millis() - start >= timeout) {
    log_d("Timeout reached, this can be caused by a slow network or a slow client, check underlying client.");
  }
  
  int result = client->read(buf, len);
  
  if (!result) {
    return MBEDTLS_ERR_SSL_WANT_READ;
  }

  log_v("SSL client RX (received=%d expected=%zu in %lums)", result, len, millis()-start);
  
  if (result > 0) {
    //esp_log_buffer_hexdump_internal("SSL.RD", buf, (uint16_t)result, ESP_LOG_VERBOSE);
  }
  
  return result;
}

[Bascy]

This code works as expected, with a small change:

  if (timeout > 0 && millis() - start >= timeout) {
    log_w("Timeout (%ums) reached, this can be caused by a slow network or a slow client, check underlying client.", timeout);
  }

Small note: delay(x) on espressif-arduino is implemented as vTaskDelay(pdMS_TO_TICKS(x)); so it doent really matter which one you use.

Question: Have you used the SSLClient with an Ethernet Client underneath? If so, which EthernetClient implementation did you use?

[RobertByrnes]

"Small note: delay(x) on espressif-arduino is implemented as vTaskDelay(pdMS_TO_TICKS(x)); so it doent really matter which one you use." Well you learn something new every day 💯

Yep of course - handle the zero timeout!

I've not used this lib with an Ethernet client as yet only with WiFi / GSM but I'd be tempted by something from here because of the active maintenance schedule Arduino Core

Will PR from this branch with the updated logging condition. Is there anything around this issue relating to this library rather than an underlying client to look at that you are aware of?

[Bascy]

The Eth repo in arduno-esp32 looks very interesting, definetly will have a look at it (too bad that other dependencies we are using, like eModbus already use (forks of) arduino-libraries/Ethernet).

I have added an issue about the availability count at arduino-libraries/Ethernet (arduino-libraries/Ethernet#259)

I'm not aware of any other problems with using this repo in combination with SSL