adafruit / Adafruit_CircuitPython_Requests

Requests-like interface for web interfacing
MIT License
51 stars 36 forks source link

MemoryError making SSL Requests, Complex, Consistently Reproducible #197

Open gsexton opened 5 days ago

gsexton commented 5 days ago

I have a Raspberry Pi Pico W running CircuitPython 9.0.5. I'm using the current version (HEAD) of Adafruit_CircuitPython_Requests, and the current HEAD of Adafruit_CircuitPython_ConnectionManager. The application files are compiled using mpy-cross 9.0.5. The size of the .mpy files is approximately 22K bytes and code.py is about 9K bytes.

My application is a thermometer with a LCD display. I'm using a TMP102, and an Adafruit ST7789 240x320 display. The display shows the current temp and time. Temperature readings are taken once a second, averaged, and once a minute, the program does a POST request to place the temperature data into an InfluxDB on a remote host. I'm also using Adafruit_CircuitPython_NTP at startup to set the RTC. Finally, I'm making requests to the OpenWeather API. The OpenWeather API call is made once per 10 minutes. I ran into problems with SSL certificates. If I tried to make requests to more than one SSL site, I immediately ran out of memory. To work around that, I made a proxy for the OpenWeather API on the same server that hosts Influx. Also, I'm using a GoDaddy cert, so I load the GoDaddy CA certificate using this code:

def network_helper.init(xxxx,xxx,xxx)
    pool = socketpool.SocketPool(wifi.radio)
    ctx = ssl.create_default_context()
    ctx.check_hostname = False
    requests = adafruit_requests.Session(pool, ctx)
    with open('/godaddy.pem') as f:
        certs = f.read()
    ctx.load_verify_locations(cadata=certs)
    return True, requests

so I'm only calling one SSL http host. The requests session is created:

result, http_requests = network_helper.init_network(configuration_values.WIFI_COUNTRY, configuration_values.WIFI_SSID, configuration_values.WIFI_PSK, led=led)
influx = InfluxWriter(configuration_values.INFLUX_HOST, configuration_values.INFLUX_DB, http_requests)

        def _send_request(self, reqbody):  ## ReqBody is around 32 bytes...
            try:
                with self.parent._session.post(self.parent.target_url, data=reqbody, headers=InfluxWriter.request_headers) as r:
                    if r.status_code != STATUS_OK and r.status_code != STATUS_NO_CONTENT:
                        logging.error("making influx post request. Status code: {status_code} body={reqbody}\nContent=\n{content}",
                                      status_code=r.status_code, reqbody=reqbody, content=r.content)
                    r.close()
            except Exception as e:
                logging.error("InfluxWriter._send_request(body={reqbody}) Exception: {e} {etype}", reqbody=reqbody, e=e, etype=type(e))
                return False
            return True

This worked pretty well for a year or so using CircuitPython 8.x.

What's happening is that about 7 minutes after startup, I start getting memory errors.

0;���🐍Wi-Fi: No IP | code.py | 9.0.5[01/01/2020 00:00:08] INFO Connect result = None
[01/01/2020 00:00:08] INFO Connected to wifi mhsoftware!
[01/01/2020 00:00:08] INFO My MAC Addr ['0x28', '0xcd', '0xc1', '0x3', '0x2f', '0xc0']
[01/01/2020 00:00:08] INFO My IP Address is 192.168.168.110
[01/01/2020 00:00:08] INFO Netmask: 255.255.255.0
[01/01/2020 00:00:08] INFO Gateway: 192.168.168.1
[01/01/2020 00:00:08] INFO DNS Server: 192.168.168.1
[01/01/2020 00:00:08] INFO network_helper.set_time(ntp_server="192.168.168.1", tz_offset=-7)
[01/01/2020 00:00:08] INFO Setting RTC Clock to: struct_time(tm_year=2024, tm_mon=6, tm_mday=29, tm_hour=6, tm_min=58, tm_sec=57, tm_wday=5, tm_yday=181, tm_i)
[06/29/2024 06:59:03] INFO network_helper.set_time(ntp_server="192.168.168.1", tz_offset=-6.0)
[06/29/2024 06:59:03] INFO Setting RTC Clock to: struct_time(tm_year=2024, tm_mon=6, tm_mday=29, tm_hour=7, tm_min=59, tm_sec=2, tm_wday=5, tm_yday=181, tm_is)
[06/29/2024 08:08:07] ERROR InfluxWriter._send_request(body=tempmon,sensor=otext temp=71.57) Exception:  <class 'MemoryError'>
[06/29/2024 08:20:12] ERROR InfluxWriter._send_request(body=tempmon,sensor=otext temp=71.64) Exception:  <class 'MemoryError'>
[06/29/2024 08:22:11] ERROR InfluxWriter._send_request(body=tempmon,sensor=otext temp=71.57) Exception:  <class 'MemoryError'>

About every other call results in a MemoryError. After some time, failures become more prevalent.

[06/29/2024 15:03:05] ERROR OpenWeather API Exception: 
Body=
Response=None
[06/29/2024 15:03:42] ERROR InfluxWriter._send_request(body=tempmon,sensor=otext temp=72.92) Exception:  <class 'MemoryError'>
[06/29/2024 15:04:42] ERROR InfluxWriter._send_request(body=tempmon,sensor=otext temp=72.95) Exception:  <class 'MemoryError'>
[06/29/2024 15:06:44] ERROR InfluxWriter._send_request(body=tempmon,sensor=otext temp=72.96) Exception:  <class 'MemoryError'>
[06/29/2024 15:08:43] ERROR InfluxWriter._send_request(body=tempmon,sensor=otext temp=72.94) Exception:  <class 'MemoryError'>
[06/29/2024 15:09:44] ERROR InfluxWriter._send_request(body=tempmon,sensor=otext temp=73.02) Exception:  <class 'MemoryError'>
[06/29/2024 15:11:43] ERROR InfluxWriter._send_request(body=tempmon,sensor=otext temp=72.89) Exception:  <class 'MemoryError'>

I added some dumps of gc value, and can see when I enter the loop there's some 60K bytes free. After the first http requests, free memory reduces to about 20 K Bytes:

[06/29/2024 14:42:25] DEBUG Top of while Loop. GC: Allocated: 61952  Free: 61440
[06/29/2024 14:42:28] DEBUG Post InfluxWrite and gc.collect() GC: Allocated: 93760  Free: 29632
[06/29/2024 14:42:29] DEBUG Post OpenWeather getCurrentTemp() GC: Allocated: 95248  Free: 28144
[06/29/2024 14:42:29] INFO network_helper.set_time(ntp_server="192.168.168.1", tz_offset=-6.0)
[06/29/2024 14:42:29] DEBUG time poll=3
[06/29/2024 14:42:29] INFO Setting RTC Clock to: struct_time(tm_year=2024, tm_mon=6, tm_mday=29, tm_hour=15, tm_min=42, tm_sec=27, tm_wday=5, tm_yday=181, tm_)
[06/29/2024 15:42:28] DEBUG Weather Current Temp=79.38
[06/29/2024 15:42:28] DEBUG Pre gc.collect() GC: Allocated: 108320  Free: 14508
[06/29/2024 15:42:29] DEBUG Top of while Loop. GC: Allocated: 100240  Free: 22588
[06/29/2024 15:42:30] DEBUG Post InfluxWrite and gc.collect() GC: Allocated: 100240  Free: 22588
[06/29/2024 15:42:30] DEBUG Post OpenWeather getCurrentTemp() GC: Allocated: 106512  Free: 16316

After a MemoryError, it looks like:

[06/29/2024 15:49:42] DEBUG Pre gc.collect() GC: Allocated: 102000  Free: 20048
[06/29/2024 15:49:43] DEBUG Top of while Loop. GC: Allocated: 100064  Free: 21984
[06/29/2024 15:49:44] DEBUG Pre gc.collect() GC: Allocated: 102000  Free: 20048
[06/29/2024 15:49:45] DEBUG Top of while Loop. GC: Allocated: 100064  Free: 21984
[06/29/2024 15:49:45] ERROR InfluxWriter._send_request(body=tempmon,sensor=otext temp=73.68) Exception:  <class 'MemoryError'>
[06/29/2024 15:49:45] DEBUG Post InfluxWrite and gc.collect() GC: Allocated: 69392  Free: 52656

You can see that AFTER a memory error, a great deal more of memory is freed. I've noticed that free memory and allocated memory are unchanged UNLESS I use the requests library. IOW, reading the TMP102 and updating the display DON'T change the free memory.

[06/29/2024 15:52:49] DEBUG Top of while Loop. GC: Allocated: 100064  Free: 21984
[06/29/2024 15:52:49] DEBUG Pre gc.collect() GC: Allocated: 102000  Free: 20048
[06/29/2024 15:52:50] DEBUG Top of while Loop. GC: Allocated: 100064  Free: 21984
[06/29/2024 15:52:50] DEBUG Pre gc.collect() GC: Allocated: 102000  Free: 20048
[06/29/2024 15:52:51] DEBUG Top of while Loop. GC: Allocated: 100064  Free: 21984
[06/29/2024 15:52:51] DEBUG Pre gc.collect() GC: Allocated: 102000  Free: 20048

Observations

So what seems to be happening is that calling the API library to make a request consumes around 40 K Bytes. When an error occurs, around 30KB is freed giving about 50K bytes free. A subsequent call consumes around 30K bytes. The call after that fails with out of memory.

Does anyone have any ideas on how to work around this? I feel like trying to follow conventional memory reduction techniques is just going to be useless since evidence shows the requests library consuming most of it.

gsexton commented 5 days ago

Looking at adafruit_connectionmanager(), I'm not understanding how this will work without a call to gc.collect()

        try:
            socket = self._get_connected_socket(
                addr_info, host, port, timeout, is_ssl, ssl_context
            )
            self._register_connected_socket(key, socket)
            return socket
        except (MemoryError, OSError, RuntimeError):
            # Could not get a new socket (or two, if SSL).
            # If there are any available sockets, free them all and try again.
            if self.available_socket_count:
                self._free_sockets()
                socket = self._get_connected_socket(
                    addr_info, host, port, timeout, is_ssl, ssl_context
                )
                self._register_connected_socket(key, socket)
                return socket
            # Re-raise exception if no sockets could be freed.
            raise
justmobilize commented 5 days ago

Python will free memory when it can't find enough. When the sockets are freed, they can be gc'd when the system needs it.

Once everything is loaded into memory, you should be able to constantly make calls, unless you are holding onto data locally (like keeping the weather data). Are you making sure everything is freed?

Also, you could look at the json streamer as it can pull data in chunks (vs the whole string and the json conversation).

gsexton commented 5 days ago

@justmobilize Thanks for replying.

I changed the openweather code to save just the keys out of the response dict that I'm using. It's about 6 or so. This didn't make any difference. I'm still seeing the memory error on every other request to influx. I never got any memory error while parsing the OpenWeather API.

The influx writer doesn't allocate any memory. It formats a string and calls .post(). You can see on the first run-through that the memory allocation ratchets up on the first call. to the .post() call.

[06/29/2024 14:42:25] DEBUG Top of while Loop. GC: Allocated: 61952  Free: 61440
[06/29/2024 14:42:28] DEBUG Post InfluxWrite and gc.collect() GC: Allocated: 93760  Free: 29632

So, calling request.post() immediately consumes 1/4th of the RAM of the system and doesn't free it.

justmobilize commented 5 days ago

If you want to make sure the sockets are fully cleared you can call:

adafruit_connection_manager.connection_manager_close_all()

Which will release all the open sockets. You could then do a gc.collect() as well.

The other issue is you need continuous memory. So if you have fragmentation it could slowly build until it's unusable.

I often do a soft reset when I get to a point of not needing anything that's loaded.

9.x did change how it managed memory, and for most it was helpful, but seems to have made the pico worse.

dhalbert commented 5 days ago

Please try the "Absolute Newest" build via the link on the board page. We turned off some things that will free up some RAM.

gsexton commented 2 days ago

@dhalbert I tried with 9.1.0-beta.3-55-g95dbb18d22 and the issue still occurs.

justmobilize commented 2 days ago

Did you try adding the adafruit_connection_manager.connection_manager_close_all()?