Thread Lock timeout INFO level messages

[JohnJ9ml]

When I see these, it just doesn't feel that right to me. What causes this, and why do they linger so?

09/07/2025 09:51:47 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec0b40> 09/07/2025 09:51:48 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:48 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:48 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:48 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:49 AM [proxy] [DEBUG] 192.168.1.111 "GET /api/sitemaster HTTP/1.1" 200 - 09/07/2025 09:51:49 AM [pypowerwall.tedapi.pypowerwall_tedapi] [DEBUG] -- tedapi: Request for /api/sitemaster 09/07/2025 09:51:49 AM [pypowerwall.tedapi.pypowerwall_tedapi] [DEBUG] This API [get_api_sitemaster] is using mock data in tedapi mode. 09/07/2025 09:51:49 AM [proxy] [DEBUG] 192.168.1.111 "GET /api/meters/aggregates HTTP/1.1" 200 - 09/07/2025 09:51:49 AM [pypowerwall.tedapi.pypowerwall_tedapi] [DEBUG] -- tedapi: Request for /api/meters/aggregates 09/07/2025 09:51:49 AM [proxy] [DEBUG] 192.168.1.111 "GET /api/powerwalls HTTP/1.1" 200 - 09/07/2025 09:51:49 AM [pypowerwall.tedapi.pypowerwall_tedapi] [DEBUG] -- tedapi: Request for /api/powerwalls 09/07/2025 09:51:49 AM [pypowerwall.tedapi.pypowerwall_tedapi] [DEBUG] This API [get_api_powerwalls] is using mock data in tedapi mode. 09/07/2025 09:51:49 AM [proxy] [DEBUG] 192.168.1.111 "GET /api/system_status/soe HTTP/1.1" 200 - 09/07/2025 09:51:49 AM [pypowerwall.tedapi.pypowerwall_tedapi] [DEBUG] -- tedapi: Request for /api/system_status/soe 09/07/2025 09:51:49 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:49 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:49 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec0b40> 09/07/2025 09:51:49 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:49 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec0b40> 09/07/2025 09:51:49 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:49 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec0b40> 09/07/2025 09:51:50 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:50 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec0b40> 09/07/2025 09:51:50 AM [proxy] [DEBUG] 192.168.1.111 "GET /api/system_status/grid_status HTTP/1.1" 200 - 09/07/2025 09:51:50 AM [pypowerwall.tedapi.pypowerwall_tedapi] [DEBUG] -- tedapi: Request for /api/system_status/grid_status 09/07/2025 09:51:50 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec0b40> 09/07/2025 09:51:50 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec0b40> 09/07/2025 09:51:50 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:51 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:51 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec0b40> 09/07/2025 09:51:51 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec1500> 09/07/2025 09:51:51 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec0b40> 09/07/2025 09:51:51 AM [pypowerwall.api_lock] [INFO] Timeout for <locked _thread.lock object at 0x7ffef9ec0b40> 09/07/2025 09:51:51 AM [pypowerwall.tedapi] [ERROR] Error fetching config: HTTPSConnectionPool(host='192.168.91.1', port=443): Read timed out. (read timeout=5) 09/07/2025 09:51:51 AM [pypowerwall.tedapi] [ERROR] Error fetching status: HTTPSConnectionPool(host='192.168.91.1', port=443): Read timed out. (read timeout=5) 09/07/2025 09:51:51 AM [pypowerwall.api_lock] [INFO] Timeout for <unlocked _thread.lock object at 0x7ffef9ec0b40>

[jasonacox]

Automated Root Cause Analysis

The proxy is experiencing API lock timeouts due to a combination of factors:

1. Network Connectivity Issues: The logs show HTTPSConnectionPool(host='192.168.91.1', port=443): Read timed out. (read timeout=5) - this indicates network timeouts when trying to reach the Tesla Gateway at 192.168.91.1.

2. Lock Contention: Multiple concurrent requests are trying to access the same TEDAPI endpoints simultaneously, but the underlying network calls are timing out, causing locks to be held longer than expected.

3. Lock Timeout Logging: The api_lock.py mechanism logs "Timeout for " every time it fails to acquire a lock during its exponential backoff attempts.

What's Happening

1. TEDAPI Mode: The proxy is running in TEDAPI mode (direct communication with Tesla Gateway at 192.168.91.1)
2. Network Issues: The Gateway is experiencing network connectivity issues or is overloaded
3. Lock Buildup: When network calls timeout, the locks are held for the full 5-second timeout period
4. Cascading Effect: Multiple proxy requests pile up, each waiting for locks, creating more timeout messages
5. Exponential Backoff: The lock acquisition uses exponential backoff, generating multiple "Timeout" log messages per failed attempt

Why They Linger

The locks "linger" because:

• Each network call has a 5-second timeout
• When network calls fail, threads hold locks for the full duration
• The exponential backoff mechanism keeps trying to acquire locks, logging each timeout attempt
• Multiple concurrent requests compound the problem

[jasonacox]

@JohnJ9ml - Here is a new pypowerwall proxy that removes those timeout notices (moves them to debug) if you want to test: jasonacox/pypowerwall:0.14.2t82-beta2

[JohnJ9ml]

I wasn't so much concerned about their being at INFO level - I run the thing at DEBUG level anyway - as much as concerned there might be an underlying issue. Only reason I brought it up.