Errors and warnings from pyPowerwall

[jgleigh]

2023-04-21 17:58:20 04/21/2023 05:58:20 PM [proxy] [INFO] pyPowerwall [0.6.2] Proxy Server [t25] - HTTP Port 8675
2023-04-21 17:58:20 04/21/2023 05:58:20 PM [proxy] [INFO] pyPowerwall Proxy Started

Everyday or so:

2023-04-27 02:15:00 04/27/2023 02:15:00 AM [proxy] [ERROR] Missing key in payload [PINV_Fout]
2023-04-27 02:15:00 04/27/2023 02:15:00 AM [proxy] [ERROR] Missing key in payload [PINV_VSplit1]
2023-04-27 02:15:00 04/27/2023 02:15:00 AM [proxy] [ERROR] Missing key in payload [PINV_VSplit2]

and lots of:

2023-04-27 03:57:45 04/27/2023 03:57:45 AM [urllib3.connectionpool] [WARNING] Connection pool is full, discarding connection: 192.168.1.6. Connection pool size: 10

and occasionally strange errors like this:

2023-04-21 16:09:05 ----------------------------------------
2023-04-21 16:09:05 Exception occurred during processing of request from ('172.22.0.2', 57742)
2023-04-21 16:09:05 Traceback (most recent call last):
2023-04-21 16:09:05 File "/usr/local/lib/python3.10/socketserver.py", line 683, in process_request_thread
2023-04-21 16:09:05 self.finish_request(request, client_address)
2023-04-21 16:09:05 File "/usr/local/lib/python3.10/socketserver.py", line 360, in finish_request
2023-04-21 16:09:05 self.RequestHandlerClass(request, client_address, self)
2023-04-21 16:09:05 File "/usr/local/lib/python3.10/socketserver.py", line 747, in init
2023-04-21 16:09:05 self.handle()
2023-04-21 16:09:05 File "/usr/local/lib/python3.10/http/server.py", line 433, in handle
2023-04-21 16:09:05 self.handle_one_request()
2023-04-21 16:09:05 File "/usr/local/lib/python3.10/http/server.py", line 421, in handle_one_request
2023-04-21 16:09:05 method()
2023-04-21 16:09:05 File "/app/server.py", line 227, in do_GET
2023-04-21 16:09:05 pod["PW%d_POD_ActiveHeating" % idx] = int(get_value(d, 'POD_ActiveHeating'))
2023-04-21 16:09:05 TypeError: int() argument must be a string, a bytes-like object or a real number, not 'NoneType'
2023-04-21 16:09:05 ----------------------------------------

2023-04-20 20:31:20 ----------------------------------------
2023-04-20 20:31:20 Exception occurred during processing of request from ('172.22.0.4', 50576)
2023-04-20 20:31:20 Traceback (most recent call last):
2023-04-20 20:31:20 File "/usr/local/lib/python3.10/socketserver.py", line 683, in process_request_thread
2023-04-20 20:31:20 self.finish_request(request, client_address)
2023-04-20 20:31:20 File "/usr/local/lib/python3.10/socketserver.py", line 360, in finish_request
2023-04-20 20:31:20 self.RequestHandlerClass(request, client_address, self)
2023-04-20 20:31:20 File "/usr/local/lib/python3.10/socketserver.py", line 747, in init
2023-04-20 20:31:20 self.handle()
2023-04-20 20:31:20 File "/usr/local/lib/python3.10/http/server.py", line 433, in handle
2023-04-20 20:31:20 self.handle_one_request()
2023-04-20 20:31:20 File "/usr/local/lib/python3.10/http/server.py", line 421, in handle_one_request
2023-04-20 20:31:20 method()
2023-04-20 20:31:20 File "/app/server.py", line 202, in do_GET
2023-04-20 20:31:20 for device in vitals:
2023-04-20 20:31:20 TypeError: 'NoneType' object is not iterable
2023-04-20 20:31:20 ----------------------------------------

[mcbirse]

@jgleigh - I can't really comment on the other errors, however can on this one...

2023-04-27 03:57:45 04/27/2023 03:57:45 AM [urllib3.connectionpool] [WARNING] Connection pool is full, discarding connection: 192.168.1.6. Connection pool size: 10

Check here for some background on this: jasonacox/pypowerwall#20

This is pretty normal behaviour when using persistent HTTP connections and I don't believe the WARNING is anything to be concerned about.

There is a default pool size limit of 10 for persistent connections however. What that means is, up to 10 connections to the local gateway will be established simultaneously to serve the API requests (and no more). Those connections are re-used for requests, which is much more efficient than opening/closing a connection for each request (see thread link above for my testing on this).

You could adjust/increase the pool size if you like (see thread for the config option), however be aware the Tesla gateway may actually limit the number of simultaneous HTTP connections allowed (have not tested).

[jgleigh]

I'm going to try PW_POOL_MAXSIZE=15 to see if it reduces to number of times the pool fills up.

[jasonacox]

@mcbirse is correct for the connection recycling.

I get the errors as well, happens a few times a week. It never reached the threshold of making me want to investigate since it doesn't impact my graphs. Are you seeing dropouts or other data issue in the graphs?

2023-04-27 02:15:00 04/27/2023 02:15:00 AM [proxy] [ERROR] Missing key in payload [PINV_Fout]

These are the result of an incomplete protobuf payload from the Powerwall. I have thought about adding logic to ignore missing keys to mute the errors, but it may mask a more significant problem. Alternatively, I thought about have it retry when a payload is incomplete.

2023-04-21 16:09:05 File "/app/server.py", line 227, in do_GET
2023-04-21 16:09:05 pod["PW%d_POD_ActiveHeating" % idx] = int(get_value(d, 'POD_ActiveHeating'))
2023-04-21 16:09:05 TypeError: int() argument must be a string, a bytes-like object or a real number, not 'NoneType'

Similar to above, this is due to an incomplete payload that is missing a key (POD_ActiveHeating). The get_value() function returns None when the key is missing. Additional error logic could be added, but I didn't want to mask a bigger issue. The "retry" idea may be good here.

Why does the payload sometimes fail (missing or corrupt keys)? Is this an anomaly on the Powerwall not generating a full payload? Is it a network/firewall issue? Is it pypowerwall or the connection pool recycling? I'm going to add a bit more debug output (e.g. drop the full payload) to see if I can determine what is happening. It could just be a network connection issue, or it could be some forced connection timeout dropping the TCP session in mid-stream.

[jgleigh]

@jasonacox No dropouts or data issues that I've noticed, just the log messages. I haven't seen any dropped connections since I increased the pool to 15 (early today).

[mcbirse]

I changed the pool max size to 15 as well a week ago... have not seen any "Connection pool is full" warnings since then either, when I used to see them semi-occasionally.

It seems a max pool size of 15 might be a more sensible default. Perhaps a change to the default that is set internally in the pypowerwall proxy should be considered?

i.e.

pool_maxsize = int(os.getenv("PW_POOL_MAXSIZE", "15"))

I haven't noticed any adverse affects of increasing the pool to 15.

[jasonacox]

Great idea @mcbirse ! I updated the default in pypowerwall proxy t26 to be 15. See #268 and https://github.com/jasonacox/pypowerwall/blob/355bcdf761dc3da73fd473f902125da7a1f2036c/proxy/server.py#L43-L57