Avian’s Blog

A side note to my previous post about using delays to save power on an ESP8266 web server. When I was using Apache Bench to measure the server response times, I noticed that the total time for a request to the ESP8266 always seemed to be about 2 seconds:

$ ab -n10 http://esp8266.lan/
This is ApacheBench, Version 2.3 <$Revision: 1843412 $>

...

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        2   16  36.6      4     120
Processing:  2006 2008   4.0   2007    2017
Waiting:        5    7   3.9      6      16
Total:       2009 2024  39.7   2010    2137

This looked odd. When opened in a browser, there was no noticeable 2 second delay and the page from the ESP8266 web server displayed immediately.

The way Apache Bench displays the Connection Times numbers is a bit odd to begin with. This post tells how to interpret the Connect, Processing and Waiting rows. In short, Processing is time from start to end of the TCP connection. Waiting is time from when the request was sent to when the first byte of the response was received.

Since Waiting time was short, this led me to believe that the whole response is sent quickly, but the connection is not closed until after a 2 second delay. A quick tcpdump confirmed this:

(client opens connection)
17:43:27.892032 IP client.lan:55422 > esp8266.lan:80: Flags [S], seq 3077448494, win 64240, options [mss 1460,sackOK,TS val 3187045141 ecr 0,nop,wscale 7], length 0
17:43:27.923811 IP esp8266.lan:80 > client.lan:55422: Flags [S.], seq 6555, ack 3077448495, win 2144, options [mss 536], length 0
17:43:27.923855 IP client.lan:55422 > esp8266.lan:80: Flags [.], ack 1, win 64240, length 0
(client sends request)
17:43:27.923968 IP client.lan:55422 > esp8266.lan:80: Flags [P.], seq 1:83, ack 1, win 64240, length 82: HTTP: GET / HTTP/1.0
(esp8266 sends response)
17:43:27.929828 IP esp8266.lan:80 > client.lan:55422: Flags [P.], seq 1:85, ack 83, win 2062, length 84: HTTP: HTTP/1.0 200 OK
17:43:27.929861 IP client.lan:55422 > esp8266.lan:80: Flags [.], ack 85, win 64156, length 0
17:43:27.931314 IP esp8266.lan:80 > client.lan:55422: Flags [P.], seq 85:97, ack 83, win 2062, length 12: HTTP
17:43:27.931337 IP client.lan:55422 > esp8266.lan:80: Flags [.], ack 97, win 64144, length 0
(esp8266 closes connection - note 2 s delay in timestamps)
17:43:29.934077 IP esp8266.lan:80 > client.lan:55422: Flags [F.], seq 97, ack 83, win 2062, length 0
17:43:29.934227 IP client.lan:55422 > esp8266.lan:80: Flags [F.], seq 83, ack 98, win 64143, length 0
17:43:29.936098 IP esp8266.lan:80 > client.lan:55422: Flags [.], ack 84, win 2061, length 0

In HTTP/1.0, the server should close the connection as soon as the complete response has been sent. It seems that ESP8266WebServer does this differently for some reason. Instead of the server closing the connection, it waits for the client to close it. There's also a timeout that closes the connection from the server side if it's not closed by the client. The timeout is controlled by the HTTP_MAX_CLOSE_WAIT constant, which is set to 2 seconds.

This is weird, because ESP8266 even sends a Connection: close header in the response, explicitly signaling to the client that the server will close the connection.

I think this is due to a benign bug in the ESP8266WebServer's state machine. After spending some time looking at the source, it seems like the current code intends to properly implement both keep-alive and non-keep-alive connections, but for some reason still uses the client timeout in the later case.

I wanted to dig a bit deeper into this and perhaps send a pull request, but instead I spent a bunch of time trying to get the current git version of ESP8266 core for Arduino to work with my ESP8266 modules. This turned out to be a whole new can of worms.