ESP8266(ESP-WROOM-02)の内容。ESP-WROOM-32ではないので注意。

事象

esp8266 -> nginx(proxy) -> python(HTTPServer)という構成でサーバへespからサーバーへリクエストを投げたところ、かなりの確率で以下のログがpythonで吐かれていた。

Exception occurred during processing of request from ('127.0.0.1', 48024)
Traceback (most recent call last):
  File "/usr/lib/python3.10/socketserver.py", line 316, in _handle_request_noblock
    self.process_request(request, client_address)
  File "/usr/lib/python3.10/socketserver.py", line 347, in process_request
    self.finish_request(request, client_address)
  File "/usr/lib/python3.10/socketserver.py", line 360, in finish_request
    self.RequestHandlerClass(request, client_address, self)
  File "/usr/lib/python3.10/socketserver.py", line 747, in __init__
    self.handle()
  File "/usr/lib/python3.10/http/server.py", line 433, in handle
    self.handle_one_request()
  File "/usr/lib/python3.10/http/server.py", line 421, in handle_one_request
    method()
  File "/home/yoshitake/api/mail_api.py", line 26, in do_GET
    self.wfile.write(response_content)
  File "/usr/lib/python3.10/socketserver.py", line 826, in write
    self._sock.sendall(b)
BrokenPipeError: [Errno 32] Broken pipe

直接のメッセージは、pythonがリクエスト元に書きこもうとしたら相手がすでに受信待ち状態を終了しているような場合に起きるやつ。esp側では接続したもののヘッダーも取得せずにすぐに終了している。

ちなみにnginxのaccess.logには以下のようにステータス499と（pythonのHTTPServer他で使われている非標準の）クライアントが先に閉じたよというのが残っている。

150.9.94.220 - - [26/Feb/2024:11:31:56 +0900] "GET /api/reserve_count HTTP/1.0" 499 0 "-" "ESP8266"

直接の原因箇所

リクエストを送るesp側でデータの受信待ちをしなくてすぐに閉じているのが直接の原因

BearSSL::WiFiClientSecure client;
client->write("GET ");
client->write(path);
client->write(" HTTP/1.0\r\nHost: ");
client->write(host);
client->write("\r\nUser-Agent: ESP8266\r\n");
client->write("\r\n");
//ヘッダー書き込みの後
//delay(1000);　みたいな待ちがなく
while (client->available()) { // すぐにデータ有無を確認し、おそらくパイソン側の準備ができずに
    char c = client->read();
    Serial.write(c);
}
client->stop();// 終了している

delay(1000);とかを入れたらとりあえず動く。

とはいえ、リクエストを送ったのちにデータ受信後の終了信号的なものをみたらまたはタイムアウトでクローズの方がよさそう。

また、同じ接続方式でself-signed.badssl.comにリクエストを送るとレスポンスがきちんと取得できているのでサーバサイドにも何か改善点がありそう。

根本解決

クライアントサイド(ESP8266)

取り急ぎavailable()では接続できたかしか確認していない。　WiFiServerSecureBearSSL.cpp（サーバの方）を間違えてみていた。

// Return a client if there's an available connection waiting.  If one is returned,
// then any validation (i.e. client cert checking) will have succeeded.
WiFiClientSecure WiFiServerSecure::available(uint8_t* status) {

改めてWiFiClientSecureBearSSL.cpp確認。

int WiFiClientSecureCtx::_pollRecvBuffer() {
  if (_recvapp_buf) {
    return _recvapp_len;  // Anything from last call?
  }
  _recvapp_buf = nullptr;
  _recvapp_len = 0;
  if (!ctx_present() || _run_until(BR_SSL_RECVAPP, false) < 0) {
    return 0;
  }
  int st = br_ssl_engine_current_state(_eng);
  if (st == BR_SSL_CLOSED) {
    return 0;  // Nothing leftover, SSL is closed
  }
  if (st & BR_SSL_RECVAPP) {
    _recvapp_buf = br_ssl_engine_recvapp_buf(_eng, &_recvapp_len);
    return _recvapp_len;
  }

  return 0;
}

字面で見る限りなんか入ってたら0以外が入って、なにも入っていないとサーバ側が準備中でも一番下に入って0がくるっぽい。だいぶ中の方に書いてあるので内部データを見ると色々多変そうなので最初のデータ来るかタイムアウトまでの待ち処理を入れるのがよさそう。断続的にデータがくるならちゃんと終端処理を見た方がよいかも。

本体から、書き出しメソッド呼び出し。

  client->write("\r\n"); //リクエスト書き込みの最終行

  writeData(client); //時間待ちつつ書き出しメソッド呼び出し

  client->stop();// 切断

void writeData(BearSSL::WiFiClientSecure *client) {
  uint32_t timeout = millis() + 5000;

  while (!client->available()) {
    if (millis() > timeout) return;
    yield();
  }

  while (client->available()) {
    char c = client->read();
    Serial.write(c);
  }
}

サーバサイド(nginx+pythonのHTTPServer)

こちらは単純にレスポンスが早く返りだすかどうかで違いが出ていたっぽい。レスポンスが早いという理由だった場合はクライアント側の処理で解決すべき話なので深く追わない。