[SOLVED] Multiple Restarts (every 45 minutes) & how to handle cronjobs then

[Alex04 (Alexander Mack)]

Platform information:
Hardware: RBP4
OS: OH
Java Runtime Environment: Java 8
openHAB version: 2.5.9

I do have basically two problems.

The first problem is, that it seems that openhab restarts every 45 minutes

2020-11-02 23:59:50.366 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_house.py'
2020-11-02 23:59:55.549 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_heatpump.py'
2020-11-03 00:00:28.031 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'my.items'
2020-11-03 00:00:28.121 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Systemair.items'
2020-11-03 00:00:28.142 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'House_Electricity.items'
2020-11-03 00:00:28.174 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Sma_Inverter.items'
2020-11-03 00:00:28.198 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Heatpump_Electricity.items'
2020-11-03 00:00:28.225 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Total_Electricity.items'
2020-11-03 00:00:28.835 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2020-11-03 00:00:29.412 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.sitemap'
2020-11-03 00:00:29.612 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'systemair_modbus.things'
2020-11-03 00:00:29.641 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sma_inverter_modbus.things'
2020-11-03 00:00:29.674 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'my.things', using it anyway:
Provide a thing type ID and a thing ID in this format:
 <thingTypeId> <thingId>
2020-11-03 00:00:29.677 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'my.things'
2020-11-03 00:00:33.029 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'my.rules'
2020-11-03 00:00:33.779 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'heatpump_electricity_calculation.rules'
2020-11-03 00:00:34.590 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'total_electricity_calculation.rules'
2020-11-03 00:00:34.935 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'house_electricity_calculation.rules'
2020-11-03 00:00:35.073 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'openhab_backup.rules'
2020-11-03 00:00:35.344 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-11-03 00:00:35.481 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'systemair_modbus.things' is either empty or cannot be parsed correctly!
2020-11-03 00:00:36.517 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.1.27:8080
2020-11-03 00:00:36.518 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.1.27:8443
2020-11-03 00:00:38.339 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid 60592de3-0a50-4726-a569-ffa5931506ff
2020-11-03 00:00:38.570 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Modbus manager activated
2020-11-03 00:00:40.668 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-11-03 00:00:50.114 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_heatpump.py'
2020-11-03 00:00:50.118 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_house.py'
2020-11-03 00:00:52.253 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Total Electricity Consumption': Could not cast NULL to java.lang.Number; line 11, column 82, length 39
2020-11-03 00:01:00.015 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_heatpump.py'
2020-11-03 00:01:00.022 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_house.py'
---
2020-11-03 00:44:33.328 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_heatpump.py'
2020-11-03 00:45:07.511 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'my.items'
2020-11-03 00:45:07.599 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Systemair.items'
2020-11-03 00:45:07.621 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'House_Electricity.items'
2020-11-03 00:45:07.651 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Sma_Inverter.items'
2020-11-03 00:45:07.674 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Heatpump_Electricity.items'
2020-11-03 00:45:07.699 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Total_Electricity.items'
2020-11-03 00:45:08.281 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2020-11-03 00:45:08.827 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.sitemap'
2020-11-03 00:45:09.020 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'systemair_modbus.things'
2020-11-03 00:45:09.050 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sma_inverter_modbus.things'
2020-11-03 00:45:09.084 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'my.things', using it anyway:
Provide a thing type ID and a thing ID in this format:
 <thingTypeId> <thingId>
2020-11-03 00:45:09.086 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'my.things'
2020-11-03 00:45:11.245 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-11-03 00:45:12.668 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'my.rules'
2020-11-03 00:45:13.449 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'heatpump_electricity_calculation.rules'
2020-11-03 00:45:14.307 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'total_electricity_calculation.rules'
2020-11-03 00:45:14.763 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'house_electricity_calculation.rules'
2020-11-03 00:45:14.810 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'openhab_backup.rules'
2020-11-03 00:45:15.060 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'systemair_modbus.things' is either empty or cannot be parsed correctly!
2020-11-03 00:45:16.153 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.1.27:8080
2020-11-03 00:45:16.155 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.1.27:8443
2020-11-03 00:45:18.003 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid 757ac3b3-1915-4f6a-915e-05c879305c6f
2020-11-03 00:45:18.224 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Modbus manager activated
2020-11-03 00:45:20.275 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-11-03 00:45:30.113 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_heatpump.py'
2020-11-03 00:45:30.119 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_house.py'
2020-11-03 00:45:31.874 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Total Electricity Consumption': Could not cast NULL to java.lang.Number; line 11, column 82, length 39
2020-11-03 00:45:40.013 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_heatpump.py'
2020-11-03 00:45:40.026 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_house.py'
2020-11-03 00:45:50.004 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_heatpump.py'
2020-11-03 00:45:50.008 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python
---
2020-11-03 01:29:00.922 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_house.py'
2020-11-03 01:29:24.428 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'my.items'
2020-11-03 01:29:24.510 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Systemair.items'
2020-11-03 01:29:24.533 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'House_Electricity.items'
2020-11-03 01:29:24.565 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Sma_Inverter.items'
2020-11-03 01:29:24.587 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Heatpump_Electricity.items'
2020-11-03 01:29:24.611 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Total_Electricity.items'
2020-11-03 01:29:25.182 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2020-11-03 01:29:25.736 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'demo.sitemap'
2020-11-03 01:29:25.950 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'systemair_modbus.things'
2020-11-03 01:29:25.979 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'sma_inverter_modbus.things'
2020-11-03 01:29:26.012 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'my.things', using it anyway:
Provide a thing type ID and a thing ID in this format:
 <thingTypeId> <thingId>
2020-11-03 01:29:26.015 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'my.things'
2020-11-03 01:29:28.107 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2020-11-03 01:29:29.540 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'my.rules'
2020-11-03 01:29:30.338 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'heatpump_electricity_calculation.rules'
2020-11-03 01:29:31.187 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'total_electricity_calculation.rules'
2020-11-03 01:29:31.632 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'house_electricity_calculation.rules'
2020-11-03 01:29:31.679 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'openhab_backup.rules'
2020-11-03 01:29:31.909 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'systemair_modbus.things' is either empty or cannot be parsed correctly!
2020-11-03 01:29:32.952 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.1.27:8080
2020-11-03 01:29:32.954 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.1.27:8443
2020-11-03 01:29:34.730 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid 5f1eaabf-bcf7-4d05-be21-4e667e7e55b5
2020-11-03 01:29:35.040 [INFO ] [rt.modbus.internal.ModbusManagerImpl] - Modbus manager activated
2020-11-03 01:29:37.237 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-11-03 01:29:44.676 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_heatpump.py'
2020-11-03 01:29:44.681 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_house.py'
2020-11-03 01:29:48.715 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Total Electricity Consumption': Could not cast NULL to java.lang.Number; line 11, column 82, length 39
2020-11-03 01:29:49.689 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Total Electricity Consumption': Could not cast NULL to java.lang.Number; line 17, column 76, length 39
2020-11-03 01:29:49.704 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Total Electricity Consumption': Could not cast NULL to java.lang.Number; line 17, column 76, length 39
2020-11-03 01:29:50.007 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_heatpump.py'
2020-11-03 01:29:50.010 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '/usr/bin/python /etc/openhab2/scripts/smartmeter_house.py'

The second problem is, that I do have a cronjob at 00:00 o clock and unfortunately it seems that exactly at this time one of the restarts mentioned above happened.
So the items did not get persisted.

Strategies {
    everyMinute : "0 * * * * ?"
    everyHour   : "0 0 * * * ?"
    everyDay    : "0 0 0 * * ?"
}

Items {
    Total_Todays_Electricity_Consumption,
    Total_Todays_Electricity_Consumption_PV,
    Total_Todays_Electricity_Consumption_Obtain,
    Total_Todays_Electricity_Supply,
    Smartmeter_Heatpump_Total_Consumption,
    Smartmeter_Heatpump_Total_Supply,
    Smartmeter_House_Total_Consumption, 
    Smartmeter_House_Total_Supply,
    Heatpump_Today_Consumption,
    Heatpump_Today_Consumption_PV,
    Heatpump_Today_Consumption_Obtain,
    House_Today_Consumption,
    House_Today_Consumption_PV,
    House_Today_Consumption_Obtain,
    SMA_Inverter_Today_Production,
    SMA_Inverter_Total_Production: strategy = everyDay, restoreOnStartup
}

So my questions are:

1. How can I solve the restarting problem.
2. What to to if a restart or a system crash happens exactly at the time a cronjob should get executed - is there any smart way to handle this? E.g. check if cronjob has been executed and if not, execute it a bit later…?

Thank you very much in advance and kind regards
Alex

[Charley]

I would start by fixing the issue in my.things first.

[Alex04 (Alexander Mack)]

Great idea - did it now but I will bet that this is not going to solve the issue

But even if it does, how can we handle a system crash exactly at the time a cronjob should be executed? This could happen at any time even if the chances are low. Therefore how could a solutione be like to get the things persisted in any case?

[rossko57]

@Alex04

But even if it does, how can we handle a system crash exactly at the time a cronjob should be executed?

You can’t. You can check to see if it was correctly carried out at some later time, and then you might do something about it. Skeleton of the idea - “When system started, is there a record for todays date yet? If not, make a record.”

General comment - exactly-at-midnight scheduled jobs often do not fare well, because you are in competition with all sorts of other system services doing housekeeping. For that reason, for an example, the Astro binding does its daily chores at 00:00:30

[Alex04 (Alexander Mack)]

Okay, that´s what I was afraid of - so I added a fallback rule for persisting:

rule "PersistenceFallback"
    when
        System started
    then
        //we should have a fallback for the case that the midnight conjob fails because of a system crash or restoreOnStartup
        //if thats the case the last save should be more than 1 day ago - save them manually
        if(Smartmeter_Heatpump_Total_Consumption.changedSince(now.minusDays(1)) == false) {
            logWarn("Persistence-Fallback:", "It seems that the cronjob persistence didn´t work at midnight, therefore we manually persist the items");
            Total_Todays_Electricity_Consumption.persist;
            Total_Todays_Electricity_Consumption_PV.persist;
            Total_Todays_Electricity_Consumption_Obtain.persist;
            Total_Todays_Electricity_Supply.persist;
            Smartmeter_Heatpump_Total_Consumption.persist;
            Smartmeter_Heatpump_Total_Supply.persist;
            Smartmeter_House_Total_Consumption.persist;
            Smartmeter_House_Total_Supply.persist;
            Heatpump_Today_Consumption.persist;
            Heatpump_Today_Consumption_PV.persist;
            Heatpump_Today_Consumption_Obtain.persist;
            House_Today_Consumption.persist;
            House_Today_Consumption_PV.persist;
            House_Today_Consumption_Obtain.persist;
            SMA_Inverter_Today_Production.persist;
            SMA_Inverter_Total_Production.persist;
        }
end

[rossko57]

Use of changedSince is clever - but will it ever have a day’s rest, i.e. update but not change?

While longhand works fine, you can make it easier to manage with use of a Group, both for persist selection and your rule.

[Alex04 (Alexander Mack)]

Use of changedSince is clever - but will it ever have a day’s rest, i.e. update but not change?

I think there will never be a day with no electricity consumption for heatpump and house ever. Even if the heatpump wouldn´t run a day, I do have a “cascaded wiring” so the smartmeter of the heatpump changes in both cases - heatpump consumption and house consumption.

So it is pretty save IMHO.

While longhand works fine, you can make it easier to manage with use of a Group, both for persist selection and your rule.

Not sure if I understand you correctly, do you mean put both - cronjob and system started event in one rule like

rule "PersistenceFallback"
    when
        System started or 
        Time cron "59 23 * * * ?"
    then
    ...
end

[rossko57]

@Alex04

Not sure if I understand you correctly

Nope - I mean put a bunch of Items into a Group.
In your xxx.persist file, you specify yourGroupName* and it automatically stores all members. Its in the docs.
In your belt&braces rule, it’s not so easy. But rather than a long list of xxx.persist(), you code to iterate through the Group members and persit each member.

The advantage is future maintenance - you can add or remove Items to the Group, in one place, and never touch persist file or rule. This just nice-to-have stuff, you need to tackle your periodic reinitializes first.

[Alex04 (Alexander Mack)]

Got it, thanks for the hint - I read a bit through the docu and will use it - makes it more stable and less likely to forget to add items to persist in that rule on future additions.

Great thanks

[rlkoshak (Rich Koshak)]

Your logs posted in the first post do not indicate that OH itself is restarting (maybe there are logs not posted). It indicates that all the text configs are all being reloaded.

OH reloads the text files when ever there is a file event on those files. Do you have something on your system that is touching, copying, refreshing, editing, etc on the files? Is the file system being remounted?

[Alex04 (Alexander Mack)]

Not as far as I know.
I only do a change in file system via a backup rule:

rule "Openhab-Backup-Script-Call"
when
  Time cron "0 0 0 3 * ? *"
then
  executeCommandLine("/bin/bash /etc/openhab2/scripts/openhab_backup_nas.sh")
end

The script contains:

#!/bin/bash

IP_NAS=192...
PWD_NAS="not telling"
USR_NAS="neither telling"
LOCATION_NAS="/Backup"
BACKUP_FILE_PREFIX="openhab_backup_"
BACKUP_DEST="/mynas/backups"
SUDO_PWD="openhabian"


TODAY=$(date +"%m_%d_%Y")
FILENAME=$BACKUP_FILE_PREFIX$TODAY

FILE_EXTENSION=".zip"

echo $SUDO_PWD | sudo -S openhab-cli backup $FILENAME

if mountpoint -q -- "$BACKUP_DEST"; then
  printf "Already mounted"
else
  echo $SUDO_PWD | sudo -S mount -t cifs -o username=$USR_NAS,password=$PWD_NAS //$IP_NAS$LOCATION_NAS $BACKUP_DEST
fi

echo $SUDO_PWD | sudo -S mv $FILENAME$FILE_EXTENSION $BACKUP_DEST

[rlkoshak (Rich Koshak)]

All I can off is that something on the machine where openHAB is running is causing all the text based configs to be reloaded periodically. It likely has nothing directly to do with openHAB (i.e. it’s not going to be in any of your openHAB configs).

[denominator (James Bowler)]

Are you running openhabian 1.6?
32bit or 64bit?

[rossko57]

This -

2020-11-03 00:00:36.517 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.1.27:8080
2020-11-03 00:00:36.518 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.1.27:8443

and other service messages are the sort of thing we usually see at system boot.
This does not at all feel like a partial reinitialize due to bindings or Things hiccuping.
I don’t know quite what happens if something ‘touches’ the timestamp of some fundamental system config file, maybe that is still a possibility.

how consistent is this 45 minutes, is it always that closely aligned to the system clock?

[Alex04 (Alexander Mack)]

I am using this version of openhab:

[16:23:48] openhabian@openhab:/var/log$ dpkg --list | grep openhab
ii  openhab2                       2.5.9-1                             all          openhab2

No its not consistent to the system clock but happens approx. every 45 minutes:

2020-11-04 14:18:47.748 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-11-04 14:18:55.695 [WARN ] [e.model.script.Persistence-Fallback:] - It seems that the cronjob persistence didn´t work at midnight, therefore we manually persist the items
2020-11-04 15:05:55.992 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'systemair_modbus.things' is either empty or cannot be parsed correctly!
2020-11-04 15:06:00.826 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-11-04 15:06:08.631 [WARN ] [e.model.script.Persistence-Fallback:] - It seems that the cronjob persistence didn´t work at midnight, therefore we manually persist the items
2020-11-04 15:51:59.445 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'systemair_modbus.things' is either empty or cannot be parsed correctly!
2020-11-04 15:52:04.676 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-11-04 15:52:12.671 [WARN ] [e.model.script.Persistence-Fallback:] - It seems that the cronjob persistence didn´t work at midnight, therefore we manually persist the items
2020-11-04 16:36:15.306 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'systemair_modbus.things' is either empty or cannot be parsed correctly!
2020-11-04 16:36:20.547 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2020-11-04 16:36:28.344 [WARN ] [e.model.script.Persistence-Fallback:] - It seems that the cronjob persistence didn´t work at midnight, therefore we manually persist the items

It seems that I have at some point not enough memory left - that`s at least how I read the system log - any idea why this is the case?

Nov  4 15:04:25 openhab influxd[28566]: ts=2020-11-04T14:04:25.319307Z lvl=info msg="Executing query" log_id=0QAwTvqW000 service=query query="SELECT value FROM openhab_db.autogen.Smartmeter_House_Total_Consumption ORDER BY time DESC LIMIT 1"
Nov  4 15:04:34 openhab influxd[28566]: [httpd] 127.0.0.1 - openhab [04/Nov/2020:15:04:24 +0100] "GET /query?db=openhab_db&epoch=ms&p=%5BREDACTED%5D&q=select+value+from+%22autogen%22.%22Smartmeter_House_Total_Supply%22+ORDER+BY+time+DESC+limit+1&u=openhab HTTP/1.1" 200 150 "-" "okhttp/2.4.0" a5184b85-1ea6-11eb-bb9a-dca6321586de 8866550
Nov  4 15:04:37 openhab influxd[28566]: [httpd] 127.0.0.1 - openhab [04/Nov/2020:15:04:24 +0100] "GET /query?db=openhab_db&epoch=ms&p=%5BREDACTED%5D&q=select+value+from+%22autogen%22.%22Smartmeter_House_Total_Consumption%22+ORDER+BY+time+DESC+limit+1&u=openhab HTTP/1.1" 200 150 "-" "okhttp/2.4.0" a5119286-1ea6-11eb-bb98-dca6321586de 8858200
Nov  4 15:04:48 openhab influxd[28566]: [httpd] 127.0.0.1 - openhab [04/Nov/2020:15:04:24 +0100] "GET /query?db=openhab_db&epoch=ms&p=%5BREDACTED%5D&q=select+value+from+%22autogen%22.%22Smartmeter_House_Total_Supply%22+ORDER+BY+time+DESC+limit+1&u=openhab HTTP/1.1" 200 150 "-" "okhttp/2.4.0" a5117a35-1ea6-11eb-bb97-dca6321586de 8889882
Nov  4 15:04:52 openhab influxd[28566]: [httpd] 127.0.0.1 - openhab [04/Nov/2020:15:04:24 +0100] "GET /query?db=openhab_db&epoch=ms&p=%5BREDACTED%5D&q=select+value+from+%22autogen%22.%22Smartmeter_House_Total_Consumption%22+ORDER+BY+time+DESC+limit+1&u=openhab HTTP/1.1" 200 150 "-" "okhttp/2.4.0" a513dc2f-1ea6-11eb-bb99-dca6321586de 8886183
Nov  4 15:05:02 openhab kernel: [748024.521551] python invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0
Nov  4 15:05:03 openhab kernel: [748024.521561] CPU: 2 PID: 1123 Comm: python Tainted: G         C        5.4.51-v7l+ #1333
Nov  4 15:05:03 openhab kernel: [748024.521565] Hardware name: BCM2711
Nov  4 15:05:03 openhab kernel: [748024.521568] Backtrace: 
Nov  4 15:05:03 openhab kernel: [748024.521581] [<c020d46c>] (dump_backtrace) from [<c020d768>] (show_stack+0x20/0x24)
Nov  4 15:05:03 openhab kernel: [748024.521587]  r6:c3546000 r5:00000000 r4:c129c8f8 r3:62d1fd98
Nov  4 15:05:03 openhab kernel: [748024.521595] [<c020d748>] (show_stack) from [<c0a39a44>] (dump_stack+0xe0/0x124)
Nov  4 15:05:03 openhab kernel: [748024.521605] [<c0a39964>] (dump_stack) from [<c037f768>] (dump_header+0x64/0x200)
Nov  4 15:05:03 openhab kernel: [748024.521610]  r8:c12056d4 r7:d5a6e680 r6:0000029e r5:eec9cc40 r4:c3547d28 r3:62d1fd98
Nov  4 15:05:03 openhab kernel: [748024.521618] [<c037f704>] (dump_header) from [<c037fde0>] (oom_kill_process+0x140/0x188)
Nov  4 15:05:03 openhab kernel: [748024.521623]  r9:c129ed08 r8:c12056d4 r7:c0dcf980 r6:c3547d28 r5:eec9d190 r4:eec9cc40
Nov  4 15:05:03 openhab kernel: [748024.521630] [<c037fca0>] (oom_kill_process) from [<c038095c>] (out_of_memory+0x120/0x340)
Nov  4 15:05:03 openhab kernel: [748024.521634]  r7:c1208380 r6:c1204f88 r5:c3547d28 r4:c1208380
Nov  4 15:05:03 openhab kernel: [748024.521642] [<c038083c>] (out_of_memory) from [<c03cea04>] (__alloc_pages_nodemask+0x106c/0x1260)
Nov  4 15:05:03 openhab kernel: [748024.521647]  r7:c1205098 r6:000002c0 r5:00000000 r4:00000000
Nov  4 15:05:03 openhab kernel: [748024.521653] [<c03cd998>] (__alloc_pages_nodemask) from [<c03793d4>] (pagecache_get_page+0x218/0x370)
Nov  4 15:05:03 openhab kernel: [748024.521658]  r10:00000044 r9:00000294 r8:c1205930 r7:d7f21be0 r6:00100cca r5:c1204f88
Nov  4 15:05:03 openhab kernel: [748024.521661]  r4:5c840003
Nov  4 15:05:03 openhab kernel: [748024.521667] [<c03791bc>] (pagecache_get_page) from [<c037a4d8>] (filemap_fault+0x7d0/0xaac)
Nov  4 15:05:03 openhab kernel: [748024.521672]  r10:c1204f88 r9:00000294 r8:d7f21be0 r7:d7f21ad8 r6:c3547ea8 r5:d430da80
Nov  4 15:05:03 openhab kernel: [748024.521675]  r4:d430da80
Nov  4 15:05:03 openhab kernel: [748024.521683] [<c0379d08>] (filemap_fault) from [<c04d59ac>] (ext4_filemap_fault+0x38/0x4c)
Nov  4 15:05:03 openhab kernel: [748024.521688]  r10:00000294 r9:00000290 r8:002b4000 r7:00000000 r6:c3547ea8 r5:c3547ea8
Nov  4 15:05:03 openhab kernel: [748024.521691]  r4:d7f21ac0
Nov  4 15:05:03 openhab kernel: [748024.521698] [<c04d5974>] (ext4_filemap_fault) from [<c03b2944>] (__do_fault+0x5c/0x170)
Nov  4 15:05:03 openhab kernel: [748024.521702]  r5:d6a76478 r4:c1204f88
Nov  4 15:05:03 openhab kernel: [748024.521709] [<c03b28e8>] (__do_fault) from [<c03b6904>] (handle_mm_fault+0x6d4/0xdbc)
Nov  4 15:05:03 openhab kernel: [748024.521714]  r8:002b4000 r7:00000000 r6:0000029f r5:00000040 r4:c1204f88
Nov  4 15:05:03 openhab kernel: [748024.521722] [<c03b6230>] (handle_mm_fault) from [<c0a5b664>] (do_page_fault+0x320/0x3a8)
Nov  4 15:05:03 openhab kernel: [748024.521727]  r10:00000000 r9:d8948c40 r8:00000207 r7:d8948c00 r6:002b4218 r5:d6b08000
Nov  4 15:05:03 openhab kernel: [748024.521730]  r4:c3547fb0
Nov  4 15:05:03 openhab kernel: [748024.521737] [<c0a5b344>] (do_page_fault) from [<c0216660>] (do_DataAbort+0x40/0xbc)
Nov  4 15:05:03 openhab kernel: [748024.521742]  r10:00000000 r9:b67204e0 r8:c3547fb0 r7:002b4218 r6:c0a5b344 r5:00000207
Nov  4 15:05:03 openhab kernel: [748024.521745]  r4:c120ab64
Nov  4 15:05:03 openhab kernel: [748024.521751] [<c0216620>] (do_DataAbort) from [<c0201d24>] (__dabt_usr+0x44/0x60)
Nov  4 15:05:03 openhab kernel: [748024.521755] Exception stack(0xc3547fb0 to 0xc3547ff8)
Nov  4 15:05:03 openhab kernel: [748024.521759] 7fa0:                                     01077760 00000002 008e15fb 002a0b80
Nov  4 15:05:03 openhab kernel: [748024.521764] 7fc0: 002a0934 b6c84bc0 002a03d8 002b41c8 001efc35 b67204e0 00000000 001efc34
Nov  4 15:05:03 openhab kernel: [748024.521769] 7fe0: 002a0b80 be9b6270 000755b4 00120bc0 20000010 ffffffff
Nov  4 15:05:03 openhab kernel: [748024.521774]  r8:30c5387d r7:30c5383d r6:ffffffff r5:20000010 r4:00120bc0
Nov  4 15:05:03 openhab kernel: [748024.521777] Mem-Info:
Nov  4 15:05:03 openhab kernel: [748024.521789] active_anon:341851 inactive_anon:113969 isolated_anon:0
Nov  4 15:05:03 openhab kernel: [748024.521789]  active_file:325 inactive_file:332 isolated_file:0
Nov  4 15:05:03 openhab kernel: [748024.521789]  unevictable:4 dirty:2 writeback:1 unstable:0
Nov  4 15:05:03 openhab kernel: [748024.521789]  slab_reclaimable:3215 slab_unreclaimable:6970
Nov  4 15:05:03 openhab kernel: [748024.521789]  mapped:839 shmem:11807 pagetables:4578 bounce:0
Nov  4 15:05:03 openhab kernel: [748024.521789]  free:7625 free_pcp:0 free_cma:336
Nov  4 15:05:03 openhab kernel: [748024.521798] Node 0 active_anon:1367404kB inactive_anon:455876kB active_file:1300kB inactive_file:1328kB unevictable:16kB isolated(anon):0kB isolated(file):0kB mapped:3356kB dirty:8kB writeback:4kB shmem:47228kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Nov  4 15:05:03 openhab kernel: [748024.521807] DMA free:21344kB min:16384kB low:20480kB high:24576kB active_anon:551092kB inactive_anon:20944kB active_file:504kB inactive_file:1172kB unevictable:0kB writepending:12kB present:786432kB managed:678476kB mlocked:0kB kernel_stack:6584kB pagetables:5528kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:1344kB
Nov  4 15:05:03 openhab kernel: [748024.521812] lowmem_reserve[]: 0 0 1254 1254
Nov  4 15:05:03 openhab kernel: [748024.521828] HighMem free:9156kB min:12800kB low:20552kB high:28304kB active_anon:816312kB inactive_anon:434932kB active_file:1028kB inactive_file:244kB unevictable:16kB writepending:0kB present:1284096kB managed:1284096kB mlocked:16kB kernel_stack:0kB pagetables:12784kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Nov  4 15:05:03 openhab kernel: [748024.521832] lowmem_reserve[]: 0 0 0 0
Nov  4 15:05:03 openhab kernel: [748024.521843] DMA: 1245*4kB (UMEC) 495*8kB (UMEC) 226*16kB (UMEC) 85*32kB (UMEC) 33*64kB (UME) 29*128kB (UE) 1*256kB (E) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 21356kB
Nov  4 15:05:03 openhab kernel: [748024.521877] HighMem: 1661*4kB (UM) 256*8kB (UM) 40*16kB (UM) 10*32kB (U) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 9652kB
Nov  4 15:05:03 openhab kernel: [748024.521906] 12812 total pagecache pages
Nov  4 15:05:03 openhab kernel: [748024.521912] 320 pages in swap cache
Nov  4 15:05:03 openhab kernel: [748024.521917] Swap cache stats: add 1265591, delete 1265272, find 435208/570443
Nov  4 15:05:03 openhab kernel: [748024.521922] Free swap  = 0kB
Nov  4 15:05:03 openhab kernel: [748024.521926] Total swap = 102396kB
Nov  4 15:05:03 openhab kernel: [748024.521931] 517632 pages RAM
Nov  4 15:05:03 openhab kernel: [748024.521936] 321024 pages HighMem/MovableOnly
Nov  4 15:05:03 openhab kernel: [748024.521940] 26989 pages reserved
Nov  4 15:05:03 openhab kernel: [748024.521945] 65536 pages cma reserved
Nov  4 15:05:03 openhab kernel: [748024.521950] Tasks state (memory values in pages):
Nov  4 15:05:03 openhab kernel: [748024.521955] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
Nov  4 15:05:03 openhab kernel: [748024.521969] [    126]     0   126     9434      587   176128      140             0 systemd-journal
Nov  4 15:05:03 openhab kernel: [748024.521976] [    146]     0   146     4522       12    49152      202         -1000 systemd-udevd
Nov  4 15:05:03 openhab kernel: [748024.521984] [    334]   100   334     5603       19    57344      149             0 systemd-timesyn
Nov  4 15:05:03 openhab kernel: [748024.521991] [    374]     0   374      923       12    28672       41             0 alsactl
Nov  4 15:05:03 openhab kernel: [748024.521998] [    375]     0   375     6378      261    57344      116             0 rsyslogd
Nov  4 15:05:03 openhab kernel: [748024.522004] [    377]   104   377     1666       91    36864       52          -900 dbus-daemon
Nov  4 15:05:03 openhab kernel: [748024.522011] [    381]     0   381     3283       49    49152      129             0 systemd-logind
Nov  4 15:05:03 openhab kernel: [748024.522017] [    386]   108   386     1507       57    ... skipped 100eds of kernal message logs here
Nov  4 15:05:03 openhab kernel: [748024.523906] [   2502]     0  2502     2078       18    32768       36             0 cron
Nov  4 15:05:03 openhab kernel: [748024.523911] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/,task=java,pid=30927,uid=110
Nov  4 15:05:03 openhab kernel: [748024.524507] Out of memory: Killed process 30927 (java) total-vm:652368kB, anon-rss:255976kB, file-rss:0kB, shmem-rss:0kB, UID:110 pgtables:812kB oom_score_adj:0
Nov  4 15:05:03 openhab kernel: [748024.575121] oom_reaper: reaped process 30927 (java), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Nov  4 15:05:06 openhab influxd[28566]: [httpd] 127.0.0.1 - openhab [04/Nov/2020:15:04:24 +0100] "GET /query?db=openhab_db&epoch=ms&p=%5BREDACTED%5D&q=select+value+from+%22autogen%22.%22Smartmeter_Heatpump_Total_Supply%22+ORDER+BY+time+DESC+limit+1&u=openhab HTTP/1.1" 200 150 "-" "okhttp/2.4.0" a51179db-1ea6-11eb-bb96-dca6321586de 8986724
Nov  4 15:05:06 openhab systemd[1]: openhab2.service: Main process exited, code=killed, status=9/KILL
Nov  4 15:05:07 openhab systemd[1]: openhab2.service: Failed with result 'signal'.
Nov  4 15:05:07 openhab influxd[28566]: ts=2020-11-04T14:05:07.389470Z lvl=info msg="Executing query" log_id=0QAwTvqW000 service=query query="SELECT value FROM openhab_db.autogen.Smartmeter_House_Total_Supply ORDER BY time DESC LIMIT 1"
Nov  4 15:05:07 openhab influxd[28566]: ts=2020-11-04T14:05:07.389474Z lvl=info msg="Executing query" log_id=0QAwTvqW000 service=query query="SELECT value FROM openhab_db.autogen.Smartmeter_House_Total_Supply ORDER BY time DESC LIMIT 1"
Nov  4 15:05:07 openhab influxd[28566]: [httpd] 127.0.0.1 - openhab [04/Nov/2020:15:05:07 +0100] "GET /query?db=openhab_db&epoch=ms&p=%5BREDACTED%5D&q=select+value+from+%22autogen%22.%22Smartmeter_House_Total_Supply%22+ORDER+BY+time+DESC+limit+1&u=openhab HTTP/1.1" 200 85 "-" "okhttp/2.4.0" be51dea8-1ea6-11eb-bb9c-dca6321586de 430433
Nov  4 15:05:07 openhab influxd[28566]: [httpd] 127.0.0.1 - openhab [04/Nov/2020:15:05:02 +0100] "GET /query?db=openhab_db&epoch=ms&p=%5BREDACTED%5D&q=select+value+from+%22autogen%22.%22Smartmeter_House_Total_Supply%22+ORDER+BY+time+DESC+limit+1&u=openhab HTTP/1.1" 200 85 "-" "okhttp/2.4.0" bd692857-1ea6-11eb-bb9b-dca6321586de 4580501
Nov  4 15:05:07 openhab CRON[2509]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Nov  4 15:05:12 openhab systemd[1]: openhab2.service: Service RestartSec=5s expired, scheduling restart.
Nov  4 15:05:12 openhab systemd[1]: openhab2.service: Scheduled restart job, restart counter is at 4.
Nov  4 15:05:12 openhab systemd[1]: Stopped openHAB 2 - empowering the smart home.
Nov  4 15:05:12 openhab systemd[1]: Started openHAB 2 - empowering the smart home.

I am not sure what the exact problem is, on the one hand side, there is the “python invoked oom-killer” message which could make me think that one of my python scripts is causing this (see below)

The other message I think is confusing is about the java space:

Nov  4 15:05:03 openhab kernel: [748024.523911] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/,task=java,pid=30927,uid=110
Nov  4 15:05:03 openhab kernel: [748024.524507] Out of memory: Killed process 30927 (java) total-vm:652368kB, anon-rss:255976kB, file-rss:0kB, shmem-rss:0kB, UID:110 pgtables:812kB oom_score_adj:0
Nov  4 15:05:03 openhab kernel: [748024.575121] oom_reaper: reaped process 30927 (java), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB

I do have a python script for reading out smartmeter SML Data:

#!/usr/bin/env python
# encoding: utf-8
"""
pysml.py
Created by Aley Mack
"""

import sys
import os
import datetime
import serial                       #needs an 'sudo -H pip install pyserial' if used via exec binding
import time
import re
import paho.mqtt.client as paho     #needs an 'sudo -H pip install paho-mqtt' if used via exec binding


#openhab remove commands
#sudo apt-get purge openhab2*
#sudo rm /etc/apt/sources.list.d/openhab2.list


# SML regexes
complete_message_regex = '1b1b1b1b01010101.*1b1b1b1b.{8}'
meter_108_regex = '77070100010800ff.{30}(.{8})01'
meter_208_regex = '77070100020800ff.{30}(.{8})01'
meter_167_regex = '77070100100700ff.{14}(.{4})01'

#MQTT Broker setup

brokerIP="192.168.*.**"
brokerPort=1883
brokerUser="Alex"
brokerPwd="notTellingHere"

#Connected Serial Device Address
serialDevice="/dev/ttyUSB1"

#Refreshing period in seconds
refreshSeconds=1
consumptionPublishedId=0
supplyPublishedId=0
currentConsumptionPublishedId=0

# Wait for mqtt client to close properly
MQTTClientConnectionClosed=0

def on_publish(client, userdata, result):
    if result == 3:
        #print "closing"
        disconnectMQTTClient(client)

def disconnectMQTTClient(client):
    client.loop_stop()
    client.disconnect()
    MQTTClientConnectionClosed=1

def on_disconnect():
    print "disconnected"

def setupMQTTBrokerClient():
    client = paho.Client("SmartMeterHousePythonClient")
    client.username_pw_set(brokerUser, brokerPwd)
    client.connect(brokerIP, brokerPort)

    client.on_publish = on_publish
    client.on_disconnect = on_disconnect
    client.loop_start()
    return client

def main():
    ser = serial.Serial(serialDevice, baudrate=9600, bytesize=8, parity='N', stopbits=1, timeout=0 )
    tty_error = 0
    searching = 1
    numberOfTrials = 0;

    client1 = setupMQTTBrokerClient()

    if tty_error == 0:
        while searching > 0 and numberOfTrials <= 100:
            numberOfTrials += 1
            data = ser.read(4096)
            data = data.encode('hex').lower()

            if re.match(complete_message_regex, data):

                m108 = re.search(meter_108_regex, data)
                m208 = re.search(meter_208_regex, data)
                m167 = re.search(meter_167_regex, data)

                if m208:
                    d208 = abs(int(m208.group(1),16)/10000.0)
                    if d208 is not None:
                        ret = client1.publish("smartmeters/house/totalSupply",d208)
                        supplyPublishedId=ret[1]
                        print "Gesamt-Einspeisung:{:.2f} KWh".format(d208)

                if m108:
                    d108 = abs(int(m108.group(1),16)/10000.0)
                    if d108 is not None:
                        ret = client1.publish("smartmeters/house/totalConsumption",d108)
                        consumptionPublishedId=ret[1]
                        print "Gesamtverbrauch: {:.3f}".format(d108)

                if m167:
                    d167 = abs(int(m167.group(1),16)/10.0)
                    if d167 is not None:
                        ret = client1.publish("smartmeters/house/currentConsumptionTotal",d167)
                        currentConsumptionPublishedId=ret[1]
                        print "Aktueller Gesamtverbrauch Haus: {:.3f}".format(d167)

                if m208 and m108 and m167:
                    searching = 0;

                #Current Usage calculated by openhab persistence
                #if m167:
                #    d167 = int(m167.group(1),16)
                #    print "Aktueller Verbrauch: {:.2f}".format(d167)

            time.sleep(refreshSeconds)

        #At this point we should have sent out all messages or aborted due to to much tries
        time.sleep(refreshSeconds)
        while MQTTClientConnectionClosed != 1:
            print "Closing connection manually"
            disconnectMQTTClient(client1)
            time.sleep(refreshSeconds)

if __name__ == '__main__':
    main()

[Alex04 (Alexander Mack)]

Ok it seems that my python scripts were running forever, because when I took a look at the pidstats it returned me the following:

[17:07:38] openhabian@openhab:~$ pidstat -r
Linux 5.4.51-v7l+ (openhab) 	11/04/2020 	_armv7l_	(4 CPU)

05:08:54 PM   UID       PID  minflt/s  majflt/s     VSZ     RSS   %MEM  Command
05:08:54 PM     0         1      0.44      0.03   33756    4252   0.22  systemd
05:08:54 PM     0       126      3.77      0.30   54104   17656   0.90  systemd-journal
05:08:54 PM     0       146      0.03      0.00   18088      48   0.00  systemd-udevd
05:08:54 PM   100       334      0.07      0.00   22412      76   0.00  systemd-timesyn
05:08:54 PM     0       374      0.01      0.00    3692      44   0.00  alsactl
05:08:54 PM     0       375      0.82      0.05   25512    1332   0.07  rsyslogd
05:08:54 PM   104       377      0.04      0.00    6664     428   0.02  dbus-daemon
05:08:54 PM     0       381      0.08      0.01   13132     200   0.01  systemd-logind
05:08:54 PM   108       386      0.22      0.02    6028     588   0.03  avahi-daemon
05:08:54 PM     0       388      0.09      0.00    8312     920   0.05  cron
05:08:54 PM 65534       395      0.03      0.01    4320      20   0.00  thd
05:08:54 PM     0       400      0.06      0.01   10740      48   0.00  wpa_supplicant
05:08:54 PM   108       403      0.00      0.00    5772       0   0.00  avahi-daemon
05:08:54 PM     0       417      0.04      0.00   27656     100   0.01  rngd
05:08:54 PM     0       455      0.07      0.02   11000      64   0.00  wpa_supplicant
05:08:54 PM     0       472      0.01      0.00   37932     272   0.01  polkitd
05:08:54 PM     0       476      0.00      0.00    2140       0   0.00  hciattach
05:08:54 PM     0       480      0.00      0.00    9536       0   0.00  bluetoothd
05:08:54 PM     0       546      0.01      0.00    2904      92   0.00  dhcpcd
05:08:54 PM     0       548      0.00      0.00   39048       0   0.00  unattended-upgr
05:08:54 PM   112       549      1.94      0.05   10308    1084   0.06  mosquitto
05:08:54 PM   110       552      3.17      0.34  155976   17636   0.90  node
05:08:54 PM   111       553      6.94      0.98  945812   29156   1.49  grafana-server
05:08:54 PM     0       558      1.49      0.09   33868    2952   0.15  nmbd
05:08:54 PM     0       567      0.00      0.00    4308       0   0.00  agetty
05:08:54 PM     0       601      0.00      0.00   10724      92   0.00  sshd
05:08:54 PM     0       664      0.05      0.00   48688    1248   0.06  smbd
05:08:54 PM     0       692      0.03      0.00   45764      48   0.00  smbd-notifyd
05:08:54 PM     0       695      0.03      0.00   45756      48   0.00  cleanupd
05:08:54 PM     0       697      0.06      0.00   48688    1640   0.08  lpqd
05:08:54 PM   110       700      0.17      0.01    6824      48   0.00  tail
05:08:54 PM     0     11641      0.00      0.00   12236     864   0.04  sshd
05:08:54 PM  1000     11653      0.00      0.00   12236    1348   0.07  sshd
05:08:54 PM  1000     11656      0.00      0.00    8856    3080   0.16  bash
05:08:54 PM   110     12797      0.09      0.00  595680  262600  13.38  java
05:08:54 PM   110     13074      0.00      0.00   28508   11724   0.60  python
05:08:54 PM   110     13076      0.00      0.00   28508   11800   0.60  python
05:08:54 PM   110     13091      0.00      0.00   28508   11944   0.61  python
05:08:54 PM   110     13093      0.00      0.00   28508   12036   0.61  python
05:08:54 PM   110     13105      0.00      0.00   28508   12000   0.61  python
05:08:54 PM   110     13107      0.00      0.00   28508   11920   0.61  python
05:08:54 PM   110     13120      0.00      0.00   28508   11940   0.61  python
05:08:54 PM   110     13122      0.00      0.00   28508   11948   0.61  python
05:08:54 PM   110     13137      0.00      0.00   28508   12040   0.61  python
05:08:54 PM   110     13139      0.00      0.00   28508   11948   0.61  python
05:08:54 PM   110     13153      0.00      0.00   28508   11960   0.61  python
05:08:54 PM   110     13155      0.00      0.00   28508   11940   0.61  python
05:08:54 PM   110     13170      0.00      0.00   28508   11948   0.61  python
05:08:54 PM   110     13181      0.00      0.00   28508   12028   0.61  python
05:08:54 PM   110     13183      0.00      0.00   28508   11928   0.61  python
05:08:54 PM   110     13195      0.00      0.00   28508   11944   0.61  python
05:08:54 PM   110     13196      0.00      0.00   28508   11936   0.61  python
05:08:54 PM   110     13208      0.00      0.00   28508   11932   0.61  python
05:08:54 PM   110     13210      0.00      0.00   28508   12036   0.61  python
05:08:54 PM   110     13229      0.00      0.00   28508   11928   0.61  python
05:08:54 PM   110     13244      0.00      0.00   28508   12028   0.61  python
05:08:54 PM   110     13246      0.00      0.00   28508   11900   0.61  python
05:08:54 PM   110     13259      0.00      0.00   28508   11940   0.61  python
05:08:54 PM   110     13261      0.00      0.00   28508   11936   0.61  python
05:08:54 PM   110     13271      0.00      0.00   28508   11948   0.61  python
05:08:54 PM   110     13272      0.00      0.00   28508   11936   0.61  python
05:08:54 PM   110     13295      0.00      0.00   28508   11872   0.60  python
05:08:54 PM   110     13309      0.00      0.00   28508   12048   0.61  python
05:08:54 PM   110     13311      0.00      0.00   28508   12004   0.61  python
05:08:54 PM   110     13333      0.00      0.00   28508   11944   0.61  python
05:08:54 PM   110     13335      0.00      0.00   28508   11928   0.61  python
05:08:54 PM   110     13350      0.00      0.00   28508   11936   0.61  python
05:08:54 PM   110     13363      0.00      0.00   28508   12056   0.61  python
05:08:54 PM   110     13364      0.00      0.00   28508   11936   0.61  python
05:08:54 PM   110     13375      0.00      0.00   28508   11908   0.61  python
05:08:54 PM   110     13377      0.00      0.00   28508   11904   0.61  python
05:08:54 PM   110     13391      0.00      0.00   28508   11948   0.61  python
05:08:54 PM   110     13393      0.00      0.00   28508   11952   0.61  python
05:08:54 PM   110     13406      0.00      0.00   28508   12016   0.61  python
05:08:54 PM   110     13407      0.00      0.00   28508   12044   0.61  python
05:08:54 PM   110     13424      0.00      0.00   28508   11952   0.61  python
05:08:54 PM   110     13437      0.00      0.00   28508   11932   0.61  python
05:08:54 PM   110     13439      0.00      0.00   28508   11952   0.61  python
05:08:54 PM   110     13453      0.00      0.00   28508   11940   0.61  python
05:08:54 PM   110     13455      0.00      0.00   28508   12040   0.61  python
05:08:54 PM   110     13468      0.00      0.00   28508   12036   0.61  python
05:08:54 PM   110     13470      0.00      0.00   28508   12008   0.61  python
05:08:54 PM   110     13481      0.00      0.00   28508   11952   0.61  python
05:08:54 PM   110     13483      0.00      0.00   28508   11868   0.60  python
05:08:54 PM   110     13497      0.00      0.00   28508   11932   0.61  python
05:08:54 PM   110     13498      0.00      0.00   28508   12040   0.61  python
05:08:54 PM   110     13511      0.00      0.00   28508   12012   0.61  python
05:08:54 PM   110     13513      0.00      0.00   28508   11952   0.61  python
05:08:54 PM   110     13526      0.00      0.00   28508   11904   0.61  python
05:08:54 PM   110     13528      0.00      0.00   28508   11904   0.61  python
05:08:54 PM   110     13540      0.00      0.00   28508   11856   0.60  python
05:08:54 PM   110     13542      0.00      0.00   28508   12040   0.61  python
05:08:54 PM   110     13557      0.00      0.00   28508   11888   0.61  python
05:08:54 PM   110     13559      0.00      0.00   28508   11940   0.61  python
05:08:54 PM   110     13571      0.00      0.00   28508   11888   0.61  python
05:08:54 PM   110     13573      0.00      0.00   28508   12012   0.61  python
05:08:54 PM   110     13585      0.00      0.00   28508   11904   0.61  python
05:08:54 PM   110     13587      0.00      0.00   28508   11940   0.61  python
05:08:54 PM   110     13601      0.00      0.00   28508   11848   0.60  python
05:08:54 PM   110     13603      0.00      0.00   28508   11952   0.61  python
05:08:54 PM   110     13617      0.00      0.00   28508   11828   0.60  python
05:08:54 PM   110     13619      0.00      0.00   28508   11936   0.61  python
05:08:54 PM   110     13631      0.00      0.00   28508   11884   0.61  python
05:08:54 PM   110     13633      0.00      0.00   28508   11940   0.61  python
05:08:54 PM   110     13645      0.00      0.00   28508   11872   0.60  python
05:08:54 PM   110     13647      0.00      0.00   28508   11952   0.61  python
05:08:54 PM   110     13657      0.00      0.00   28508   11944   0.61  python
05:08:54 PM   110     13659      0.00      0.00   28508   11908   0.61  python

Okay seems that I did the clientDisconnect in python together with loop_stop wrong.
I now do it this way:

def disconnectMQTTClient(client):
    client.disconnect()
    MQTTClientConnectionClosed=1

def on_disconnect():
    print "disconnected"
    client.loop_stop()

It seems that loop_stop() somehow were blocking and leading to an endless run. Hope that in 45 minutes I do not get a system hvm kill
But pidstats shows now not that many python processes running as before and they end at a certain time as wanted