search

jbouwh / omnikdatalogger

Datalogger for Omnik solar power inverters with DSMR integration and output to Home Assistant, PVOUTPUT, InfluxDB and MQTT
https://jbsoft.nl/site/omnik-datalogger/
GNU General Public License v3.0
10 stars 3 forks source link

The docker version of the datalogger does not connect to inverter after sunset / sunrise sequence #47

Closed joost01 closed 2 years ago

joost01 commented 2 years ago

I've updated my docker container to the latest version, as the home assistant log stated there were some legacy options used in the previous version (mdi icons). It seems to run fine (after adjusting the config directories to the new location). However, the docker container needs to be restarted daily to function normally.

Problem: The docker version of the datalogger does not connect to inverter after sunset / sunrise sequence.

When started, the logger works as aspected. The log shows: INFO:omnik.datalogger:I 2021-11-29T09:00:00.954385 New message received from inverter '' INFO:omnik.datalogger:I 2021-11-29T09:00:00.962378 Update for plant UTC 2021-11-29 08:00:00.952819+00:00

After sunrise the next day, the logger does not automatically connect to the inverter. The log shows: INFO:omnik.datalogger:I 2021-11-29T08:15:26.050094 Combining cached logging for plant with DSRM data. INFO:omnik.datalogger:I 2021-11-29T08:20:26.138647 Net data update for plant UTC 2021-11-29 07:20:01+00:00

The above message keeps repeating every 5 minutes, I dont see the message "New message received from inverter ''" in the logs until the docker container is restarted.

I did a pull from hub.docker.com and I build the container myself, both gave the same result. I've looked in the documentation for a config option that I may have missed, but couldn't find one.

jbouwh commented 2 years ago

Hi, can you tell me what client (and plugins, if any) you are using? It is true that omnikdatalogger pauses to collect data at night, but it should start again at sunrise.

joost01 commented 2 years ago

Of course!

I use only the tcpclient. For the plugins I use mqtt and pvoutput.

jbouwh commented 2 years ago

You should see a "No sunshine postponing till down next dawn" message in the log. Indicating the the polling restarts. Can you see if the logs correctly show the next poll time? You might need to turn on debug logging (loglevel: DEBUG). If your would restart the container when the sun is down you will see something like this in your logs: DEBUG:omnik:@ 2021-11-29T16:16:36.526845 new poll in 52772 seconds at 2021-11-30T07:56:09.238346+01:00.

This time is calculated using the astral library. It might go wrong if the local time is not calculated correctly.

jbouwh commented 2 years ago

I have been testing. It seems the logvel parameter loglevel is not processed (bug). But you can set debugging as follows: docker run --name omnikdatalogger -it --rm -v ${PWD}/config.yaml:/config/config.yaml -p 10004:10004 --name omnikdatalogger jbouwh/omnikdatalogger:latest -d --settings /config/config.yaml

This assumes config.yaml is in the current folder. My Inverter does not support tcpclient mode, but it is dark now. What I get is:

INFO:root:Using section 'omnikdatalogger' from config file '/config/config.yaml'
DEBUG:omnik.datalogger:@ 2021-11-29T18:56:13.424737 Data configuration [args]: ''.
DEBUG:omnik.datalogger:@ 2021-11-29T18:56:13.425092 Data configuration [path]: '/usr/local/lib/python3.9/site-packages/omnikdatalogger-1.10.1-py3.9.egg/EGG-INFO/scripts/data_fields.json'.
DEBUG:omnik.datalogger:@ 2021-11-29T18:56:13.425276 Data configuration [shared]: '/usr/local/lib/python3.9/site-packages/omnikdatalogger-1.10.1-py3.9.egg/EGG-INFO/share/omnikdatalogger/data_fields.json'.
DEBUG:omnik.datalogger:@ 2021-11-29T18:56:13.425426 Data configuration [cwd]: '/home/omnik/data_fields.json'.
INFO:omnik.datalogger:I 2021-11-29T18:56:13.425729 Using shared data configuration current working directory '/home/omnik/data_fields.json'.
INFO:omnik.datalogger:I 2021-11-29T18:56:13.426074 Cache file './persistant_cache.json' was not used previously. Error: (2, 'No such file or directory')
INFO:omnik.datalogger:I 2021-11-29T18:56:13.456201 Initializing client : tcpclient.
INFO:omnik.datalogger:I 2021-11-29T18:56:13.458140 Client enabled: TCPclient
ERROR:__main__:E 2021-11-29T18:56:13.458445 Config type error: Section: 'plugins'; Attribute: 'output'; Expected <class 'list'> got <class 'NoneType'>
WARNING:omnik.datalogger:W 2021-11-29T18:56:13.461165 No output plugins configured! Monitoring only.
INFO:__main__:I 2021-11-29T18:56:13.463959 Daemon interval 10 seconds.
INFO:omnik.datalogger:I 2021-11-29T18:56:14.468964 No sunshine postponing till down next dawn 2021-11-30 07:46:09.238346+01:00.
DEBUG:omnik.datalogger:@ 2021-11-29T18:56:14.470420 plant list from config [{'plant_id': '953'}]
INFO:omnik.datalogger:I 2021-11-29T18:56:14.470646 Initializing: Trying to reach the inverter for plant 953 over port 8899.
DEBUG:omnik.datalogger:@ 2021-11-29T18:56:14.470923 Connecting to 192.168.1.19 port 8899
INFO:omnik.datalogger:I 2021-11-29T18:56:35.527283 Inverter is not reachable over port 8899, this is normal when it is dark. [Errno 111] Connection refused
INFO:omnik.datalogger:I 2021-11-29T18:56:35.557756 Update for plant 953 UTC 2021-11-29 17:56:35.557478+00:00
DEBUG:omnik.datalogger:@ 2021-11-29T18:56:35.559259 Aggregated data processed.
DEBUG:omnik.datalogger:@ 2021-11-29T18:56:35.559501 Timed data logging processed
DEBUG:omnik:@ 2021-11-29T18:56:35.559730 new poll in 46773 seconds at 2021-11-30T07:56:09.238346+01:00.

The last line indicates the time a new poll will be initiated. Could you try this with your config?

The update you are seeing is cached data.

joost01 commented 2 years ago

I scrolled through the log, this is what I see now:

INFO:omnik.datalogger:I 2021-11-29T16:35:52.400987 New message received from inverter '<number>'
INFO:omnik.datalogger:I 2021-11-29T16:35:52.403336 Update for plant <name> UTC 2021-11-29 15:35:52.398980+00:00
INFO:omnik.datalogger:I 2021-11-29T16:42:10.204885 Inverter is not reachable over port 8899, this is normal when it is dark. [Errno 113] Host is unreachable
Exception in thread Thread-79:
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/local/lib/python3.9/threading.py", line 1266, in run
    self.function(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.9/site-packages/omnikdatalogger-1.10.1-py3.9.egg/omnik/__init__.py", line 49, in _run
    self.last_update_time = self.datalogger.process(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.9/site-packages/omnikdatalogger-1.10.1-py3.9.egg/omnik/datalogger.py", line 1338, in process
    return self._process_timed_event()
  File "/usr/local/lib/python3.9/site-packages/omnikdatalogger-1.10.1-py3.9.egg/omnik/datalogger.py", line 1250, in _process_timed_event
    self._output_update_aggregated_data(plant, aggegated_data)
  File "/usr/local/lib/python3.9/site-packages/omnikdatalogger-1.10.1-py3.9.egg/omnik/datalogger.py", line 697, in _output_update_aggregated_data
    plugin.process(msg=data)
  File "/usr/local/lib/python3.9/site-packages/omnikdatalogger-1.10.1-py3.9.egg/omnik/plugin_output/pvoutput.py", line 159, in process
    r.raise_for_status()
  File "/usr/local/lib/python3.9/site-packages/requests/models.py", line 953, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 400 Client Error: Bad Request for url: http://pvoutput.org/service/r2/addstatus.jsp
INFO:omnik.datalogger:I 2021-11-29T16:45:26.277663 Net data update for plant <name> UTC 2021-11-29 15:45:01+00:00
INFO:omnik.datalogger:I 2021-11-29T16:45:26.562143 Combining cached logging for plant <name>  with DSRM data.
INFO:omnik.datalogger:I 2021-11-29T16:50:26.626248 Net data update for plant <name> UTC 2021-11-29 15:50:01+00:00
INFO:omnik.datalogger:I 2021-11-29T16:50:26.907053 Combining cached logging for plant <name>  with DSRM data.

Now it keeps repeating the last messages every 5 minutes. After a restart this is the log:

INFO:root:Using section 'omnik_datalogger' from config file '/config/config.yaml'
INFO:omnik.datalogger:I 2021-11-29T19:35:05.325640 Using shared data configuration current working directory '/home/omnik/data_fields.json'.
INFO:omnik.datalogger:I 2021-11-29T19:35:05.329843 Using energy cache file '/config/persistant_cache.json'.
INFO:omnik.datalogger:I 2021-11-29T19:35:05.470946 Initializing client : tcpclient.
INFO:omnik.datalogger:I 2021-11-29T19:35:05.480415 Client enabled: TCPclient
INFO:omnik.datalogger:I 2021-11-29T19:35:05.481382 Output plugins configured: ['pvoutput', 'mqtt'].
INFO:omnik.datalogger:I 2021-11-29T19:35:06.972147 Initializing DSMR termimal 'term1'. Mode: tcp.
INFO:omnik.datalogger:I 2021-11-29T19:35:06.973551 MQTT connected
INFO:omnik.datalogger:I 2021-11-29T19:35:06.975713 DSMR terminal term1 was started.
INFO:__main__:I 2021-11-29T19:35:06.977094 Daemon interval 360 seconds.
INFO:omnik.datalogger:I 2021-11-29T19:35:07.994038 No sunshine postponing till down next dawn 2021-11-30 07:46:09.238346+01:00.
INFO:omnik.datalogger:I 2021-11-29T19:35:08.024342 Initializing: Trying to reach the inverter for plant <name> over port 8899.
INFO:omnik.datalogger:I 2021-11-29T19:35:11.101660 Inverter is not reachable over port 8899, this is normal when it is dark. [Errno 113] Host is unreachable
WARNING:omnik.datalogger:W 2021-11-29T19:35:14.239187 Request error: HTTPConnectionPool(host='<ip>', port=80): Max retries exceeded with url: /js/status.js (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0xb5c36940>: Failed to establish a new connection: [Errno 113] Host is unreachable'))

The postponing message is only showed after a restart, I didn't see it earlier today. Now I can watch tomorrow if the logger starts automatically. At this moment I can't start the docker container from the commandline, but that one I can do tomorrow. I can provide you the debug logging than!

Thank you for taking time to investigate this (little) problem!

jbouwh commented 2 years ago

Right. I see you had some trouble with pvoutput. The error was not handled correctly. Because of that the timer may not have been started. Recently the error handling was changed, that probably causes your issue.

jbouwh commented 2 years ago

Created a new release that should catch the HTTP errors. Also the loglevel setting is now working as expected. Let me know if your issues are solved now.

joost01 commented 2 years ago

I've downloaded the latest release from the docker hub and started it. I saw some HTTP errors (see log), but have to wait until tomorrow to see if the script is starting.

This is the latest logfile:

INFO:root:Using section 'omnik_datalogger' from config file '/config/config.yaml'
INFO:omnik.datalogger:I 2021-11-29T22:07:26.981851 Using shared data configuration current working directory '/home/omnik/data_fields.json'.
INFO:omnik.datalogger:I 2021-11-29T22:07:27.010694 Using energy cache file '/config/persistant_cache.json'.
INFO:omnik.datalogger:I 2021-11-29T22:07:27.181246 Initializing client : tcpclient.
INFO:omnik.datalogger:I 2021-11-29T22:07:27.192664 Client enabled: TCPclient
INFO:omnik.datalogger:I 2021-11-29T22:07:27.193829 Output plugins configured: ['pvoutput', 'mqtt'].
INFO:omnik.datalogger:I 2021-11-29T22:07:27.271479 Initializing DSMR termimal 'term1'. Mode: tcp.
INFO:omnik.datalogger:I 2021-11-29T22:07:27.273960 DSMR terminal term1 was started.
INFO:omnik.datalogger:I 2021-11-29T22:07:27.275054 MQTT connected
INFO:__main__:I 2021-11-29T22:07:27.276281 Daemon interval 360 seconds.
INFO:omnik.datalogger:I 2021-11-29T22:07:28.293697 No sunshine postponing till down next dawn 2021-11-30 07:46:09.238346+01:00.
INFO:omnik.datalogger:I 2021-11-29T22:07:28.311042 Initializing: Trying to reach the inverter for plant <name> over port 8899.
INFO:omnik.datalogger:I 2021-11-29T22:07:31.388976 Inverter is not reachable over port 8899, this is normal when it is dark. [Errno 113] Host is unreachable
WARNING:omnik.datalogger:W 2021-11-29T22:07:34.494307 Request error: HTTPConnectionPool(host='<ip>', port=80): Max retries exceeded with url: /js/status.js (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0xb585d040>: Failed to establish a new connection: [Errno 113] Host is unreachable'))
WARNING:omnik.datalogger:W 2021-11-29T22:07:34.783181 Unhandled HTTPerror error: 400 Client Error: Bad Request for url: http://pvoutput.org/service/r2/addstatus.jsp
joost01 commented 2 years ago

Well, finally the inverter decided to start up. Let's say today isn't very 'tropical' in the Netherlands... With the latest docker image the logging starts as it should. I verified PVOutput, over there I can see the input from the inverter.

The logfile shows this:

WARNING:omnik.datalogger:W 2021-11-30T08:47:26.334264 Request error: HTTPConnectionPool(host='<ip>', port=80): Max retries exceeded with url: /js/status.js (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0xb6b2f2e0>: Failed to establish a new connection: [Errno 113] Host is unreachable'))
WARNING:omnik.datalogger:W 2021-11-30T08:47:26.615790 Unhandled HTTPerror error: 400 Client Error: Bad Request for url: http://pvoutput.org/service/r2/addstatus.jsp
INFO:omnik.datalogger:I 2021-11-30T08:48:37.625297 Initializing: Trying to reach the inverter for plant <name> over port 8899.
INFO:omnik.datalogger:I 2021-11-30T08:48:55.964776 Inverter is not reachable over port 8899, this is normal when it is dark. [Errno 113] Host is unreachable
WARNING:omnik.datalogger:W 2021-11-30T08:48:59.038008 Request error: HTTPConnectionPool(host='<ip>', port=80): Max retries exceeded with url: /js/status.js (Caused by NewConnectionError('<urllib3.connection.HTTPConnection object at 0xb585dbe0>: Failed to establish a new connection: [Errno 113] Host is unreachable'))
WARNING:omnik.datalogger:W 2021-11-30T08:48:59.337154 Unhandled HTTPerror error: 400 Client Error: Bad Request for url: http://pvoutput.org/service/r2/addstatus.jsp
INFO:omnik.datalogger:I 2021-11-30T08:50:10.346162 Initializing: Trying to reach the inverter for plant <name> over port 8899.
INFO:omnik.datalogger:I 2021-11-30T08:50:10.853950 New message received from inverter '<serial>'
INFO:omnik.datalogger:I 2021-11-30T08:50:10.856417 Update for plant <name> UTC 2021-11-30 07:50:10.851950+00:00
INFO:omnik.datalogger:I 2021-11-30T08:56:10.741355 New message received from inverter '<serial>'
INFO:omnik.datalogger:I 2021-11-30T08:56:10.747153 Update for plant <name> UTC 2021-11-30 07:56:10.739644+00:00
INFO:omnik.datalogger:I 2021-11-30T09:02:10.584980 New message received from inverter '<serial>'
INFO:omnik.datalogger:I 2021-11-30T09:02:10.587677 Update for plant <name> UTC 2021-11-30 08:02:10.582626+00:00
INFO:omnik.datalogger:I 2021-11-30T09:08:13.009069 New message received from inverter '<serial>'
INFO:omnik.datalogger:I 2021-11-30T09:08:13.011584 Update for plant <name> UTC 2021-11-30 08:08:13.007199+00:00

I am not sure why the "unhandled HTTP errors" are popping up, but the scripts seems to handle them fine. I think the issue can be closed at this moment. Again, thank you for the really quick response!

jbouwh commented 2 years ago

The text unhandled might not be correct, because it is handled, I'll update that. Omnikdatalogger will try to connect over port 8899 first, if that fails, it will fallback to use http. I'll probably add a cache function to remember what mode the inverter supports. The ultimate test will be to see if it survives another night. As you probably know the weather is the same here :-).

jbouwh commented 2 years ago

I have updated the logging. Also the behavior of the http_only flag has been changed. If your inverter only supports http and this flag is not set, then the script will keep retrying over port 8899 and log a warning if retreiving data over http was successful but the flag was not set.

jbouwh commented 2 years ago

Hi Joost, Is your script still running?

joost01 commented 2 years ago

This morning the datalogger started automatically, so it is functioning normally at this moment. I didn't use the latest docker image yet, because I wanted to see the behaviour without manual interaction. For this version, it is working now.

I did see some strange behaviour on PVoutput. At the last update the inverter was online (last one which has the inverter temperature for example), I see strange values in the "energy used" column. At this point it counts in a 5 minute interval 10 kWh, which is not consumed at that moment. I'll look at the behaviour today, maybe it only happened once.

Tomorrow I will download the latest docker version and take a look at the logging!

jbouwh commented 2 years ago

Thnx for your response, I'll have a look at my pvoutput data aswell

jbouwh commented 2 years ago

I cannot see any strange effect in my pvoutput data: https://pvoutput.org/list.jsp?userid=84664

joost01 commented 2 years ago

Sorry for the delay. I looked at your outputs and it had the same behaviour as mine. It is visible when you open the stats of one of the previous days. At your outputs, when we look at 05-12 for instance, you see the last inverter update is at 04:15 pm. After that your used energy changes from 3.928 to 9.414 kWh. It stays there until the end of the day.

I'm not sure yet if it is the omniklogger script or something in PVoutput,

jbouwh commented 2 years ago

That is weird indeeed, this is about consuming energy, After the inverter goes down, it should use the cashed value. Can you create a new issue for this? I'll close this one.