Connection closed without response on nonexistent paths

[ansemjo]

Device and/or platform:

Device: Wemos D1 Mini / ESP8266

I've tried the latest tinyweb firmware firmware_esp8266-v1.3.4.bin as well as the latest MicroPython stable release esp8266-20191220-v1.12.bin with tinyweb precompiled to .mpy format. ^†

Description of problem:

When requesting a path that was not added as a route (i.e. something like GET /nonexistent) the connection is simply closed without returning a proper HTTP error document or status code.

Expected:

The handler for HTTPException should trigger resp.error(404) and return a Not Found error to the client.

Traceback (if applicable):

On the client:

$ curl --http1.0 --verbose 192.168.1.178/nonexistent
*   Trying 192.168.1.178:80...
* TCP_NODELAY set
* Connected to 192.168.1.178 (192.168.1.178) port 80 (#0)
> GET /nonexistent HTTP/1.0
> Host: 192.168.1.178
> User-Agent: curl/7.68.0
> Accept: */*
> 
* Recv failure: Connection reset by peer
* Closing connection 0
curl: (56) Recv failure: Connection reset by peer

The ESP8266 prints nothing on serial during this time.

Additional info:

I've attempted to modify the tinyweb.py and added a few print() statements in the response.error function .. it is called and it looks like it completes without further exceptions .. but an answer is never received at the client?

---

^†: I've commented out the import logging and replaced log.exc() calls with pass to do this trivially. This should only affect what's printed to serial though?

[belyalov]

Thanks for reporting!

Could you please provide example how library usage? Otherwise it is not clear what features in use...

[ansemjo]

Of course ..

I can reproduce the behaviour with this very minimal example:

1) Download and flash latest tinyweb release firmware_esp8266-v1.3.4.bin

curl -LO https://github.com/belyalov/tinyweb/releases/download/v1.3.4/firmware_esp8266-v1.3.4.bin
esptool.py write_flash --erase -fm dio 0 firmware_esp8266-v1.3.4.bin

2) Upload the following main.py and reset

ampy -p /dev/ttyUSB0 put main.py

main.py:

import uasyncio as asyncio
from time import sleep
import network
import tinyweb

# clear serial console
print("\x1b[2J\x1b[H", end="")

# init wireless network
print("Activating Wireless network 'Tinyweb AP' ...")
wifi = network.WLAN(network.AP_IF)
wifi.active(True)
wifi.config(essid="Tinyweb AP", channel=1, authmode=network.AUTH_OPEN)

# create webserver
print("Create webserer ...")
app = tinyweb.webserver()

@app.route("/")
async def index(rx, tx):
  tx.add_header("Content-Type", "text/plain")
  await tx._send_headers()
  await tx.send("Hello, World!\n")

@app.route("/notfound")
async def justerror(rx, tx):
  await tx.error(404)

async def main():
  print("Starting webserver on " + wifi.ifconfig()[0] + ":80 ...")
  app.run(host="0.0.0.0", port=80, loop_forever=False)

loop = asyncio.get_event_loop()
loop.create_task(main())
print("Tasks created .. starting event loop ...")
loop.run_forever()

3) Connect to Tinyweb AP and check routes with curl

$ curl --http1.0 -f 192.168.4.1/
Hello, World!
$ curl --http1.0 -f 192.168.4.1/notfound
curl: (22) The requested URL returned error: 404 MSG
$ curl --http1.0 -f 192.168.4.1/nonexistent
curl: (56) Recv failure: Connection reset by peer

[ansemjo]

As I said, I've added a few print() statements around here:

https://github.com/belyalov/tinyweb/blob/55b45d7ec1fc606f3c4c32645193b32626b4aa88/tinyweb/server.py#L466-L470

And here:

https://github.com/belyalov/tinyweb/blob/55b45d7ec1fc606f3c4c32645193b32626b4aa88/tinyweb/server.py#L181-L197

The resp.error(e.code) and await self._send_headers() do get called and I have received a response once when I forcibly added an await self.send("ERROR\n"). Could it be that the writer is closed too soon? Are we sure that it is actually done sending when await writer.aclose() is called in the finally: part?

[belyalov]

Sorry for late reply, a bit busy these days, we'll try to look at this closely on weekend.

Current assumption is likely it is required to receive all HTTP request and then send response / close conn. (currently it does not receive all request, just request line).

[mvincm]

Hello,

A couple of remarks.

1) I have try to sniff (Wireshark) whole communication between esp8266 and my browser. There is no HTTP message. Just only [RST, ACK] Seq=1 Ack=487 Win=2144 Len=0. 2) So I assume that connection is reset before constructing correct header https://github.com/belyalov/tinyweb/blob/55b45d7ec1fc606f3c4c32645193b32626b4aa88/tinyweb/server.py#L172 3) Try to do some debug with print() like @ansemjo did. Maybe for some reason gc.collect() (line: 178) is doing to much...

Best regards, MvincM

[mvincm]

Hello,

Ok. My previous assumptions were not correct. IHMO (and I have tested it) problem is in "try" and "finally" statements. As far as I know "finally" don't wait for HttpException to be done (in our case to send 404 HTTP header). To proof it/test it I have add await asyncio.sleep(1) just before await writer.aclose(). It gives enough time to do the job. This is an ugly way to do this. For now, I don't have an idea how to do this "by the book". I'm wide open to your opinion/propositions. I'm just starting my Python adventure.

P.S. I'm talking about:

https://github.com/belyalov/tinyweb/blob/55b45d7ec1fc606f3c4c32645193b32626b4aa88/tinyweb/server.py#L466-L470

https://github.com/belyalov/tinyweb/blob/55b45d7ec1fc606f3c4c32645193b32626b4aa88/tinyweb/server.py#L482-L489

[ansemjo]

If that were true, wouldn't that be an upstream bug in uasyncio? That is, if finally: does not wait for asynchronous functions in an except: to complete ... ?

[mvincm]

Hello,

It looks like... If we add uasyncio.sleep(n) (depend on latency, message size) before "writer.aclose()" or after "send" which is StreamWriter.awrite() everything works ok.

"aclose" close http stream (TCP: RST,ACK). So if "sleep" is to low there is a situation when the http header is sent but the body not.

One of my assumptions... Maybe aclose do not check IOWriteDone

https://github.com/micropython/micropython-lib/blob/b89114c8345e15d360c3707493450805c114bc8c/uasyncio.core/uasyncio/core.py#L215-L216

Any suggestions?

Best regards, MvincM

[mvincm]

After some study in MPython uasyncio and tinyweb code, I have some thoughts but also open questions.

1) I have no idea why "await resp.error(e.code)" is returning before the whole buffer/message is sent. If we give some time with async.sleep() it could happen that the http header will be sent but body not. Generally, aclose is closing TCP connection without waiting for awrite to be done.

2) So... I think that we shouldn't use aclose in finally statement (line 483). https://github.com/belyalov/tinyweb/blob/55b45d7ec1fc606f3c4c32645193b32626b4aa88/tinyweb/server.py#L483 It should be done in _tcp_server which in fact is done there https://github.com/belyalov/tinyweb/blob/55b45d7ec1fc606f3c4c32645193b32626b4aa88/tinyweb/server.py#L639

3) So IMHO we should remove L483 a let close TCP connection in _tcp_server

@belyalov What is your opinion?

Best regards, MvincM

[ansemjo]

I've tried digging into the micropython implementation of usancio after your previous comment but I couldn't quite figure it out. What you linked to, that IOWriteDone is simply a pass statement does indeed look weird and could explain why writer.aclose() is behaving the way it does.

As far as I can see, the sock.close() is only called when returning from the _tcp_server() function as a whole, i.e. it is sort of a cleanup operation. Do we ever reach that code after completing a single request? Doesn't the server stay in the while True: loop?

... Which leads me to the question: is there any negative impact of not closing the writer in the request handler? Is the connection then kept open and the browser / client just never finishes "loading"?

[belyalov]

Thank you guys for research, I'm still busy, hopefully tomorrow evening will try to summarize and try will it on device (just got new device, old one stops working)

[mvincm]

Dears @ansemjo and @belyalov

In the time of waiting for the answer, I made some more tests.

And:

1) only one place where we are closing a socket is this particular "finally" statement and every connection goes through this aclose(). This is the main handler method. 2) if we remove this aclose() there will by TCP Keep-Alive communication between client and server which is the proof that we should and we do TCP connection close. 3) "normal" (not 404) request/response are closed with this sequence without "[RST, ACK]" (100.75 is a clinet nad 100.79 is a server):

601 82.626777 192.168.100.75 192.168.100.79 TCP 54 56376 → 8081 [FIN, ACK] Seq=97 Ack=174 Win=65219 Len=0 602 82.630602 192.168.100.79 192.168.100.75 TCP 54 8081 → 56376 [ACK] Seq=174 Ack=98 Win=2047 Len=0 607 83.316180 192.168.100.79 192.168.100.75 TCP 54 8081 → 56376 [FIN, ACK] Seq=174 Ack=98 Win=2047 Len=0 608 83.316291 192.168.100.75 192.168.100.79 TCP 54 56376 → 8081 [ACK] Seq=98 Ack=175 Win=65219 Len=0

4) "normal" req/resp but without "await asyncio.sleep(1)" before aclose() looks like this. You can find that there is no FIN,ACK from server side. No time for this?

96256 4868.881359 192.168.100.75 192.168.100.79 TCP 54 56799 → 8081 [FIN, ACK] Seq=97 Ack=175 Win=65219 Len=0 96257 4868.884793 192.168.100.79 192.168.100.75 TCP 54 8081 → 56799 [ACK] Seq=175 Ack=98 Win=2047 Len=0

5) if we have "time" for full response in case of error and we send "Content-Length" header (some body not only 404 header) there will be [FIN, ACK] form client side after receiving whole content (based on Content-Length).

6) Why only error connections are ended by RST,ACK and normal are not... I have no idea for now.

Best regards, MvincM

[mvincm]

P.S. As @belyalov said. If we read the whole header (not only first line) it works "just fine". We could add one line await req.read_headers() just before https://github.com/belyalov/tinyweb/blob/55b45d7ec1fc606f3c4c32645193b32626b4aa88/tinyweb/server.py#L414 But... a) without additional asyncio.sleep() we have only FIN,ACK from client side. With wait time we have also FIN,ACK from server side (as described above). b) it doesn't explain why aclose is not waiting for awrite. Even with a normal response (or error with read_headers()). As we can see the "writer" has still something to send. c) it doesn't explain why in case without read_headers() connection is closed by RST,ACK

Good night guys!

MvincM

[mvincm]

Hello,

Tested on new version of uasyncio with a very simple HTTP server implementation. Same issue. It is not related to TinyWeb.

IMHO tip with await req.read_headers() is just fine for this issue.

Best regards, MvincM

[belyalov]

Thanks for research and long wait time.. I've got the repo, will try to fix it today by reading headers and then close connection

[belyalov]

Wohoo, fix is simple and seems it works!

$ curl -v --http1.0 -f 192.168.1.25/nonexistent
*   Trying 192.168.1.25...
* TCP_NODELAY set
* Connected to 192.168.1.25 (192.168.1.25) port 80 (#0)
> GET /nonexistent HTTP/1.0
> Host: 192.168.1.25
> User-Agent: curl/7.64.1
> Accept: */*
>
* The requested URL returned error: 404 MSG
* Closing connection 0
curl: (22) The requested URL returned error: 404 MSG

[belyalov]

Fix is also available as part of updated firmware.

[ansemjo]

Nice, thank you! Thanks to @mvincm for the research, too. :)