micropython / micropython-esp32

Old port of MicroPython to the ESP32 -- new port is at https://github.com/micropython/micropython
MIT License
673 stars 216 forks source link

EINVAL on s.close() #193

Closed manningt closed 6 years ago

manningt commented 6 years ago

ntptime.time() works fine on ESP8266 and OSX platforms.

I can't get it to work on an ESP32, as per the following trace:

>>> wlan.ifconfig()
('10.0.1.53', '255.255.255.0', '10.0.1.1', '10.0.1.1')
>>> import usocket as socket
␛[0;32mI (75948) modsocket: Initializing␛[0m
>>> NTP_QUERY = bytearray(48)
>>> NTP_QUERY[0] = 0x1b
>>> addr = socket.getaddrinfo("pool.ntp.org", 123)[0][-1]
>>> s = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
>>> s.settimeout(1)
>>> s.sendto(NTP_QUERY, addr)
48
>>> msg = s.recv(48)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
OSError: [Errno 110] ETIMEDOUT

The ESP32 module I'm using can communicate to other servers using urequests, so I don't think its a networking problem.

I do not have a sniffer to determine if the socket.sendto is sending the NTP_QUERY correctly. Adding socket.SO_REUSEADDR did not change things.

Does anyone else have ntptime.time working on an ESP32? Any suggestions on debugging?

MrSurly commented 6 years ago

I omitted the settimeout(1) call. Looks like it worked, but I didn't parse the return packet.

>>> NTP_QUERY = bytearray(48)
>>> NTP_QUERY[0] = 0x1b
>>> NTP_QUERY
bytearray(b'\x1b\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00')
>>> addr = socket.getaddrinfo("pool.ntp.org", 123)[0][-1]
>>> s = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
>>> s.sendto(NTP_QUERY, addr)
48
>>> msg = s.recv(48)
>>> msg
b'\x1c\x02\x03\xec\x00\x00\x00"\x00\x00\x0f\xb0\xc6\xa9\xd0\x90\xdd\x7f\xb9=\xdf<"Z\x00\x00\x00\x00\x00\x00\x00\x00\xdd\x7f\xbf\xafs\xb3\x04m\xdd\x7f\xbf\xafs\xb8\\\x1c'
manningt commented 6 years ago

Thanks for testing. I did additional testing and it appears the issue is the NTP_QUERY packet doesn't get sent if it's the first thing performed after STA_IF activation. RECVing the MSG worked if either (a) a urequest was performed after wlan activation or (b) the NTP_QUERY packet is sent twice.

The timeout appears to work fine.

A secondary issue is the s.close() gets a OSError: [Errno 22] EINVAL exception on the ESP32. I had a loop that would try ntptime.time() multiple times until success. The first attempt would get a timeout, presumably because the first packet wasn't set. The remaining attempts after that EINVAL exception because of the s.close() issue.

So instead of using ntptime.time() I'm using the attached function. get_ntp_time.txt

MrSurly commented 6 years ago

@manningt You sure it's not just that it times out? Does it work if you try it right after STA_IF activation with no timeout?

manningt commented 6 years ago

Yes, I'm sure that it does not time-out: without the timeout, it just hangs. I retested and here are the results:

I don't have my esp8266 dev board right now, but I think the same thing (the 1st packet doesn't get sent after WiFi init) might occur on the 8266 port. I recall the first ntptime.time() always got a timeout, hence I put it in a loop to retry. Its just that on the 8266, the s.close didn't get an exception, whereas the s.close causes an exception on the ESP32.

dpgeorge commented 6 years ago

It looks like there are some issues here to sort out. s.close() generally shouldn't raise an exception.

manningt commented 6 years ago

To reproduce the OSError: [Errno 22] then do the following after wlan.connect():

import usocket as socket
NTP_QUERY = '\x1b' + 47 * '\0'
addr = socket.getaddrinfo("pool.ntp.org", 123)[0][-1]
s = socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
s.sendto(NTP_QUERY, addr)
s.sendto(NTP_QUERY, addr)
msg = s.recv(48)
s.close()

This is not a show-stopper for my application

dpgeorge commented 6 years ago

I think the timeout issue is just because UDP is an unreliable connection.

The close() issue seems to be a problem with the IDF, reported here: https://github.com/espressif/esp-idf/issues/1094

dpgeorge commented 6 years ago

In 02f94f7ed55ab69af9ae0fe9b9beeda418277fef I updated the ESP IDF to the latest version and the socket.close() issue for UDP sockets is resolved. In dba3796e3d2ea6e2d05d16c07170314a6330d73a I symlinked the ntptime.py module so that it's included with the build (following esp8266) and verified that it works correctly.