Flipping messages: Production became unavailable/Production turned on

[ridderr]

Describe the bug I do see very regular messages Production became unavailable/Production turned on in the log files

Account type

• [X ] Installer
• [ ] DIY / DHZ
• [ ] Home Owner (This integration is not (fully) functional with a home owner account!)

Envoy

• [22] Metered with CTs installed

• [ ] Metered without CTs

• [ ] Standard

• FW version: D7.6.175

• Amount of micro inverters connected:22

Home Assistant

• Version: 2023.7.2

Additional context I checked the logfile and noticed that the requests are either made with IPv4 or IPv6. When made with IPv6 I do see some errors in the log file. I can share both log file but please tell be which data (Tokens?) I have to mascaraed. Below some information

IPV6 log `2023-07-19 06:38:25.471 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://[fdd4:5e60:243a:0:82f5:b5ff:fe70:3479]/api/v1/production: Header:{} Cookies:<Cookies[<Cookie sessionId=Mql0Nf93i5Qte55jSXsvvod4p45j6kU5 for [fdd4:5e60:243a:0:82f5:b5ff:fe70:3479].local />]> 2023-07-19 06:38:27.537 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://[fdd4:5e60:243a:0:82f5:b5ff:fe70:3479]/api/v1/production: <Response [200 OK]>: { "wattHoursToday": 57, "wattHoursSevenDays": 249346, "wattHoursLifetime": 10510655, "wattsNow": 207 }

2023-07-19 06:38:27.541 INFO (MainThread) [custom_components.enphase_envoy.envoy_reader] - FETCHING ENDPOINT endpoint_production_v1_results TOOK 2.0696 seconds 2023-07-19 06:38:27.542 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_production_json_results.storage[0] 2023-07-19 06:38:27.542 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_production_json_results.storage[0] did not return anything! 2023-07-19 06:38:27.542 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_ensemble_json_results[0].devices 2023-07-19 06:38:27.542 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_ensemble_json_results[0].devices did not return anything! 2023-07-19 06:38:27.543 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_home_json_results.enpower.grid_status 2`

IPv4 log `2023-07-19 06:37:41.847 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://192.168.10.31/api/v1/production: Header:{} Cookies:<Cookies[<Cookie sessionId=Mql0Nf93i5Qte55jSXsvvod4p45j6kU5 for 192.168.10.31 />]> 2023-07-19 06:37:42.131 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://192.168.10.31/api/v1/production: <Response [200 OK]>: { "wattHoursToday": 52, "wattHoursSevenDays": 249346, "wattHoursLifetime": 10510651, "wattsNow": 199 }

2023-07-19 06:37:42.134 INFO (MainThread) [custom_components.enphase_envoy.envoy_reader] - FETCHING ENDPOINT endpoint_production_v1_results TOOK 0.2865 seconds 2023-07-19 06:37:42.135 INFO (MainThread) [custom_components.enphase_envoy.envoy_reader] UPDATING ENDPOINT endpoint_devstatus: https://{}/ivp/peb/devstatus 2023-07-19 06:37:42.135 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://192.168.10.31/ivp/peb/devstatus: Header:{} Cookies:<Cookies[<Cookie sessionId=Mql0Nf93i5Qte55jSXsvvod4p45j6kU5 for 192.168.10.31 />]> 2023-07-19 06:37:42.410 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://192.168.10.31/ivp/peb/devstatus: <Response [200 OK]>: { "counters": {"pcu": {"expected": 22,"discovered": 22,"ctrlsTotal": 22,"ctrlsGone": 0,"ctrlsCommunicating": 22,"chansTotal": 22,"chansRecent": 22,"chansProducing": 22}, "acb": {"expected": 0,"discovered": 0,"ctrlsTotal": 0,"ctrlsGone": 0,"ctrlsCommunicating": 0,"chansTotal": 0,"chansRecent": 0,"chansProducing": 0}, "nsrb": {"expected": 2,"discovered": 2,"ctrlsTotal": 2,"ctrlsGone": 0,"ctrlsCommunicating": 2,"chansTotal": 2,"chansRecent": 2,"chansProducing": 0}, "pld": {"expected": 24,"discovered": 24,"ctrlsTotal": 24,"ctrlsGone": 0,"ctrlsCommunicating": 24,"chansTotal": 24,"chansRecent": 24,"chansProducing": 22}, "esub": {"expected": 0,"discovered": 0,"ctrlsTotal": 0,"ctrlsGone": 0,"ctrlsCommunicating": 0,"chansTotal": 0,"chansRecent": 0,"chansProducing": 0}}, "pcu": {"fields": ["serialNumber", "devType", "communicating", "recent", "producing", "reportDate", "temperature", "dcVoltageINmV", "dcCurrentINmA", "acVoltageINmV", "acPowerINmW"], "values": [["122122080954", 1, true, true, true, 1689741410, 18, 32241, 553, 235496, 12150], ["122122078003", 1, true, true, true, 1689741351, 18, 32213, 551, 234928, 11114], ["122122080580", 1, true, true, true, 1689741170, 17, 31052, 384, 235488, 10247], ["122122080773", 1, true, true, true, 1689741171, 17, 31491, 397, 235776, 10160], ["122122070887", 1, true, true, true, 1689741352, 18, 32677, 532, 234912, 11097], ["122122076240", 1, true, true, true, 1689741291, 17, 31296, 391, 235624, 8842], ["122122069990", 1, true, true, true, 1689741141, 17, 31152, 371, 235928, 10265], ["122122075335", 1, true, true, true, 1689741141, 17, 31455, 391, 235768, 10157], ["122122080576", 1, true, true, true, 1689741232, 17, 31485, 426, 235464, 9849], ["122122070007", 1, true, true, true, 1689741293, 17, 31417, 351, 236048, 8616], ["122122070027", 1, true, true, true, 1689741326, 17, 31169, 356, 235328, 8322], ["122122070029", 1, true, true, true, 1689741412, 18, 31326, 264, 235744, 5273], ["122122070055", 1, true, true, true, 1689741413, 18, 31750, 287, 235520, 5683], ["122122070163", 1, true, true, true, 1689741414, 18, 31910, 286, 235464, 5703], ["122122069955", 1, true, true, true, 1689741414, 18, 32162, 274, 235400, 5916], ["122122070034", 1, true, true, true, 1689741415, 18, 31509, 287, 236944, 6588], ["122220089488", 1, true, true, true, 1689741416, 17, 31537, 439, 236216, 9610], ["122221015614", 1, true, true, true, 1689741417, 18, 31237, 418, 236360, 9445], ["122221011599", 1, true, true, true, 1689741418, 17, 30834, 374, 235576, 9026], ["122221014884", 1, true, true, true, 1689741418, 17, 31209, 465, 236536, 10697], ["122221014181", 1, true, true, true, 1689741420, 17, 31493, 486, 236568, 11113], ["122221011562", 1, true, true, true, 1689741421, 17, 30461, 329, 236248, 8958], ["122251092586", 12, true, true, false, 1689741303, 0, 0, 0, 0, 0], ["122244051652", 12, true, true, false, 1689741304, 0, 0, 0, 0, 0]]}, "acb": {"fields": ["serialNumber", "SOC", "minCellTemp", "maxCellTemp", "capacity", "totVoltage", "sleepEnabled", "sleepMinSoc", "sleepMaxSoc" ], "values": []}, "nsrb": {"fields": ["serialNumber", "relay", "forced", "reason_code", "reason", "line-count", "line1-connected", "line2-connected", "line3-connected"], "values": [["122251092586", "closed", false, -1, "ok", 1, true, false, false], ["122244051652", "closed", false, -1, "ok", 1, true, false, false]]}} 2023-07-19 06:37:42.414 INFO (MainThread) [custom_components.enphase_envoy.envoy_reader] - FETCHING ENDPOINT endpoint_devstatus TOOK 0.2788 seconds `

[vincentwolsink]

It looks like it is alternating between IPv4 or IPv6 or doing requests to both at the same time. That should not happen. Are you sure you only have one instance of the plugin configured (just to double check)?

[ridderr]

Yes, I think I only have one instance running, I do only see one entry in Devices & Services which is showing 25 devices (Envoy, 22 inverters + 2 Q relays) and 160 entities. I only have one subfolder enphase_envoy in custom_components

[vincentwolsink]

Did you configure the integration manually, if so, which IP/hostname did you enter during configuring? Or did you use the autodetect feature?

[ridderr]

Yes, I did a manual installation and entered the IPv4 address. 192.168.10.31

[ridderr]

Maybe this helps, which shows the pattern.

Envoy 122125025835 Relay 122244051652 detected 17:57:33 - 3 hours ago Envoy 122125025835 Relay 122244051652 became unavailable 17:57:21 - 3 hours ago Envoy 122125025835 Relay 122244051652 detected 17:57:20 - 3 hours ago Envoy 122125025835 Relay 122244051652 became unavailable 17:57:10 - 3 hours ago Envoy 122125025835 Relay 122244051652 detected 17:01:41 - 4 hours ago Envoy 122125025835 Relay 122244051652 became unavailable 17:01:21 - 4 hours ago Envoy 122125025835 Relay 122244051652 detected 17:01:21 - 4 hours ago Envoy 122125025835 Relay 122244051652 became unavailable 17:00:55 - 4 hours ago

[mnederlof]

If the data update takes longer than 30 seconds (envoy too slow/ha too busy/etc) this can trigger the unavailable state

We should investigate if this is the issue though

I'll try to see if I can find some code examples for you to change if that would resolve the issue

[mnederlof]

@ridderr
Try something like this: https://github.com/vincentwolsink/home_assistant_enphase_envoy_installer/compare/main...mnederlof:timeout-update

Then, increase your update interval (though configuration) to like 60 or 120 seconds, and see if the problem is now gone.

[vincentwolsink]

I didn't test it yet. But I expect #51 to fix this issue.

[ridderr]

Ok, change made. Minimum time between entity updates set to 120 and min. time between real-time updates set to 60. I will check the log for new messages (or not :-)).

[mnederlof]

I didn't test it yet. But I expect #51 to fix this issue.

yes, that could be it too.

[ridderr]

Hi, This didn't solved the issue. Already had two "Production not available" and "Production is enabled" messages

[mnederlof]

Hi, This didn't solved the issue. Already had two "Production not available" and "Production is enabled" messages

Ah, that is too bad, then at least that has been ruled out as an issue.

[vincentwolsink]

Try 0.3.0-beta3. You might need to completely remove the integration and configure it again.

[ridderr]

Hi, just installed and indeed had to configure the integration again. Let's hope this will fix the issue.

[ridderr]

Hi, the discovery service is now popping up constantly that a new integration has been found, When I enter the logon information it says that the integration is already installed. I'm not sure if the problem has been solved. The last message was "Production became unavailable" but it is still reporting. The graphs looks much better now (no gaps). I have debugging enabled. I can share these when you tell me which data I have to masquerade.

[vincentwolsink]

Hi @ridderr, I noticed this behavior too and fixed it in the latest beta. Please upgrade 🙂

[ridderr]

Hi Vincent, looks good now. many thanks