Fresh openHABian Installation various problems (no logs, amanda and mosquitto not working)

narf27 · August 13, 2021, 10:56am

Platform Information:

###############################################################################
##        Ip = 192.168.178.80
##   Release = Raspbian GNU/Linux 10 (buster)
##    Kernel = Linux 5.10.52-v7l+
##  Platform = Raspberry Pi 4 Model B Rev 1.1
##    Uptime = 4 day(s). 15:50:10
## CPU Usage = 2.75% avg over 4 cpu(s) (4 core(s) x 1 socket(s))
##  CPU Load = 1m: 0.00, 5m: 0.04, 15m: 0.06
##    Memory = Free: 2.14GB (56%), Used: 1.65GB (44%), Total: 3.79GB
##      Swap = Free: 0.53GB (100%), Used: 0.00GB (0%), Total: 0.53GB
##      Root = Free: 2.90GB (43%), Used: 3.77GB (57%), Total: 7.00GB
##   Updates = 19 apt updates available.
##  Sessions = 1 session(s)
## Processes = 141 running processes of 32768 maximum processes
###############################################################################

                          _   _     _     ____   _
  ___   ___   ___   ___  | | | |   / \   | __ ) (_)  ____   ___
 / _ \ / _ \ / _ \ / _ \ | |_| |  / _ \  |  _ \ | | / _  \ / _ \
| (_) | (_) |  __/| | | ||  _  | / ___ \ | |_) )| || (_) || | | |
 \___/|  __/ \___/|_| |_||_| |_|/_/   \_\|____/ |_| \__|_||_| | |
      |_|                          3.2.0.M1 - Milestone Build

installation summary:
august, 2: installation openHABian unattended
august, 3: fixed amanda problem with your help
august, 4: installed influxdb+grafana and applied fix
august, 6: switch from openHAB stable to milestone
august, 8: (manually) installed the ip-observer binding (everything seemed to work then, took a look a the logs around on 2021-08-08 20:22)
august, 9: didn’t get my daily backup-mail and found orther problems.

the system still worked on the evening of august, 8 and had some problems the day after. i didn’t change anything on my system in the meantime.

These are the problems i noticed:

amanda backup not working anymore (got the mails every night before that date):

[13:24:07] backup@ohab3:~$ amcheck openhab-dir
amcheck: critical (fatal): create debug directory "/var/log/amanda/server/": Permission denied
amcheck: create debug directory "/var/log/amanda/server/": Permission denied
[13:24:14] backup@ohab3:~$ amreport openhab-dir
amreport: critical (fatal): create debug directory "/var/log/amanda/server/": Permission denied
amreport: create debug directory "/var/log/amanda/server/": Permission denied

no logs on frontail, no log files on files system:

openhabian@ohab3:~ $ ls /var/log/openhab
ls: cannot access '/var/log/openhab': No such file or directory

later (when i looked aht the logs on the console) i also noticed problems with mosquitto :

20:03:26.015 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'mqtt.things'
20:03:26.109 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:mosq' changed from OFFLINE (COMMUNICATION_ERROR): io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: localhost/127.0.0.1:1883 to OFFLINE
20:03:26.113 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:mosq' changed from OFFLINE (COMMUNICATION_ERROR): io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: localhost/127.0.0.1:1883 to OFFLINE
20:03:26.117 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid openHAB3
20:03:26.132 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:mosq' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): Timeout
20:03:26.146 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:mosq' changed from OFFLINE (COMMUNICATION_ERROR): Timeout to OFFLINE (COMMUNICATION_ERROR): io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: localhost/127.0.0.1:1883
20:03:36.132 [INFO ] [t.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'localhost'. Next attempt in 60000ms
20:03:36.140 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:mosq' changed from OFFLINE (COMMUNICATION_ERROR): io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: localhost/127.0.0.1:1883 to OFFLINE
20:03:36.145 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid openHAB3
20:03:36.155 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:mosq' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: localhost/127.0.0.1:1883
20:04:36.151 [INFO ] [t.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'localhost'. Next attempt in 60000ms
20:04:36.157 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:mosq' changed from OFFLINE (COMMUNICATION_ERROR): io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: localhost/127.0.0.1:1883 to OFFLINE
20:04:36.161 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid openHAB3
20:04:36.178 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:mosq' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): io.netty.channel.AbstractChannel$AnnotatedConnectException: Connection refused: localhost/127.0.0.1:1883
.
.
.
etc.

additional infos:

openhabian@ohab3:~ $ df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/root       7.1G  3.8G  3.0G  57% /
devtmpfs        1.7G     0  1.7G   0% /dev
tmpfs           1.9G     0  1.9G   0% /dev/shm
tmpfs           1.9G   26M  1.9G   2% /run
tmpfs           5.0M     0  5.0M   0% /run/lock
tmpfs           1.9G     0  1.9G   0% /sys/fs/cgroup
/dev/sda3       7.3G  272M  6.7G   4% /storage
/dev/mmcblk0p1  253M   49M  204M  20% /boot
/dev/zram1      324M  177M  123M  60% /opt/zram/zram1
overlay1        324M  177M  123M  60% /var/lib/openhab/persistence
/dev/zram2      324M   28M  271M  10% /opt/zram/zram2
overlay2        324M   28M  271M  10% /var/lib/influxdb
/dev/zram3      420M   11M  379M   3% /opt/zram/zram3
overlay3        420M   11M  379M   3% /var/log
tmpfs           389M     0  389M   0% /run/user/1000

zram:

openhabian@ohab3:~ $ zramctl
NAME       ALGORITHM DISKSIZE   DATA COMPR  TOTAL STREAMS MOUNTPOINT
/dev/zram3 zstd          450M  25.9M  2.1M    13M       4 /opt/zram/zram3
/dev/zram2 zstd          350M  91.4M 56.7M  65.2M       4 /opt/zram/zram2
/dev/zram1 zstd          350M 212.2M  3.5M 105.8M       4 /opt/zram/zram1
/dev/zram0 lzo-rle       450M     4K   86B     4K       4 [SWAP]
openhabian@ohab3:~ $ zramctl --version
zramctl from util-linux 2.33.1

Peter

mstormi · August 13, 2021, 11:32am

No I said “no history” because that is useless and does hurt, it is confusing to every reader.
First thing thats needs to be identified is “what changed”. Nothing starts going wrong without a change. So explain the difference between when it worked and when it does not.
Rework your post, please.

narf27 · August 13, 2021, 12:14pm

i deleted the journalctl entry and made inserted a (short) summary of my installation process.
it didn’t go wrong immediately when i changed something on the system, so i must have to do with something i did some time before?

zramctl, df -h and cat /var/log/openhab output still there as you requested these on the other thread.

mstormi · August 13, 2021, 9:53pm

Try installing again. There has been a bugfix that may help you.

narf27 · August 15, 2021, 7:48am

installed from scratch (openhabian.conf edit on auto backup, hostname and mail), installed influxdb+grafana and mosquitto over openhabian-config. made a reboot afterwards and i don’t think things are running as they should:

openhabian@ohab3:~ $ cat /var/log/openhab
cat: /var/log/openhab: No such file or directory

[09:40:23] backup@ohab3:/home/openhabian$ amcheck openhab-dir
amcheck: critical (fatal): create debug directory "/var/log/amanda/server/": Permission denied
amcheck: create debug directory "/var/log/amanda/server/": Permission denied
openhabian@ohab3:~ $ sudo ls -l /var/log/amanda/server/
ls: cannot access '/var/log/amanda/server/': No such file or directory

openhabian@ohab3:~ $ df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/root       7.1G  3.2G  3.6G  47% /
devtmpfs        1.8G     0  1.8G   0% /dev
tmpfs           1.9G     0  1.9G   0% /dev/shm
tmpfs           1.9G  9.4M  1.9G   1% /run
tmpfs           5.0M     0  5.0M   0% /run/lock
tmpfs           1.9G     0  1.9G   0% /sys/fs/cgroup
/dev/sda3       7.3G   73M  6.8G   2% /storage
/dev/mmcblk0p1  253M   49M  204M  20% /boot
/dev/zram1      324M  380K  299M   1% /opt/zram/zram1
overlay1        324M  380K  299M   1% /var/lib/openhab/persistence
/dev/zram2      324M  384K  299M   1% /opt/zram/zram2
overlay2        324M  384K  299M   1% /var/lib/influxdb
/dev/zram3      420M  960K  388M   1% /opt/zram/zram3
overlay3        420M  960K  388M   1% /var/log
tmpfs           388M     0  388M   0% /run/user/1000

openhabian@ohab3:~ $ zramctl
NAME       ALGORITHM DISKSIZE  DATA COMPR TOTAL STREAMS MOUNTPOINT
/dev/zram3 zstd          450M 16.6M 72.5K  500K       4 /opt/zram/zram3
/dev/zram2 zstd          350M 16.3M  5.1K  184K       4 /opt/zram/zram2
/dev/zram1 zstd          350M 16.3M  3.7K  156K       4 /opt/zram/zram1
/dev/zram0 lzo-rle       450M    4K   86B    4K       4 [SWAP]

openhabian@ohab3:~ $ systemctl status grafana-server.service
● grafana-server.service - Grafana instance
   Loaded: loaded (/lib/systemd/system/grafana-server.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Sun 2021-08-15 09:36:08 CEST; 10min ago
     Docs: http://docs.grafana.org
  Process: 1396 ExecStart=/usr/sbin/grafana-server --config=${CONF_FILE} --pidfile=${PID_FILE_DIR}/grafana-server.pid --
 Main PID: 1396 (code=exited, status=1/FAILURE)

Aug 15 09:36:08 ohab3 systemd[1]: grafana-server.service: Service RestartSec=100ms expired, scheduling restart.
Aug 15 09:36:08 ohab3 systemd[1]: grafana-server.service: Scheduled restart job, restart counter is at 5.
Aug 15 09:36:08 ohab3 systemd[1]: Stopped Grafana instance.
Aug 15 09:36:08 ohab3 systemd[1]: grafana-server.service: Start request repeated too quickly.
Aug 15 09:36:08 ohab3 systemd[1]: grafana-server.service: Failed with result 'exit-code'.
Aug 15 09:36:08 ohab3 systemd[1]: Failed to start Grafana instance.

Wolfgang_S · August 15, 2021, 9:31am

I would suggest to have a look to the complete log entries of journalctl since last boot. It may give a hint of what is going wrong:

sudo journalctl -b

mstormi · August 15, 2021, 10:36am

Please check if you have the latest zram installed:

wget https://raw.githubusercontent.com/ecdye/zram-config/main/zram-config
diff zram-config /usr/local/sbin/zram-config

narf27 · August 15, 2021, 4:27pm

openhabian@ohab3:~ $ diff zram-config /usr/local/sbin/zram-config
168a169,192
>               if dpkg -s 'grafana' &> /dev/null && [[ $(systemctl is-active grafana-server.service) == "active" ]]; then
>                       export grafanaActive="true"
>                       systemctl stop grafana-server.service >> "$ZLOG" 2>&1 || return 1
>               fi
>               if dpkg -s 'influxdb' &> /dev/null && [[ $(systemctl is-active influxdb.service) == "active" ]]; then
>                       export influxdbActive="true"
>                       systemctl stop influxdb.service >> "$ZLOG" 2>&1 || return 1
>               fi
>               if dpkg -s 'mosquitto' &> /dev/null && [[ $(systemctl is-active mosquitto.service) == "active" ]]; then
>                       export mosquittoActive="true"
>                       systemctl stop mosquitto.service >> "$ZLOG" 2>&1 || return 1
>               fi
>               if dpkg -s 'nginx' &> /dev/null && [[ $(systemctl is-active nginx.service) == "active" ]]; then
>                       export nginxActive="true"
>                       systemctl stop nginx.service >> "$ZLOG" 2>&1 || return 1
>               fi
>               if dpkg -s 'samba' &> /dev/null && [[ $(systemctl is-active smbd.service) == "active" ]]; then
>                       export sambaActive="true"
>                       systemctl stop smbd.service nmbd.service >> "$ZLOG" 2>&1 || return 1
>               fi
>               if dpkg -s 'openhab' &> /dev/null && [[ $(systemctl is-active openhab.service) == "active" ]]; then
>                       export openhabActive="true"
>                       systemctl stop openhab.service >> "$ZLOG" 2>&1 || return 1
>               fi
184a209,226
>               fi
>               if [[ -n $openhabActive ]]; then
>                       systemctl restart openhab.service >> "$ZLOG" 2>&1 || return 1
>               fi
>               if [[ -n $sambaActive ]]; then
>                       systemctl restart smbd.service nmbd.service >> "$ZLOG" 2>&1 || return 1
>               fi
>               if [[ -n $nginxActive ]]; then
>                       systemctl restart nginx.service >> "$ZLOG" 2>&1 || return 1
>               fi
>               if [[ -n $mosquittoActive ]]; then
>                       systemctl restart mosquitto.service >> "$ZLOG" 2>&1 || return 1
>               fi
>               if [[ -n $influxdbActive ]]; then
>                       systemctl restart influxdb.service >> "$ZLOG" 2>&1 || return 1
>               fi
>               if [[ -n $grafanaActive ]]; then
>                       systemctl restart grafana-server.service >> "$ZLOG" 2>&1 || return 1

output:

mstormi · August 15, 2021, 9:39pm

Sorry I gave a wrong URL. Please try again.

narf27 · August 16, 2021, 6:05am

openhabian@ohab3:~ $ diff zram-config /usr/local/sbin/zram-config
241a242
>               rm -fv "${TMPDIR}"/zram-device-list.new >> "$ZLOG"
271c272,273
<                                                       echo "Entry ${entry} already exists as a zram device, skipping recreation of device." >> "$ZLOG"
---
>                                                       echo "Entry ${entry} already exists as a zram device, skipping recreation of device."
>                                                       echo "$entry" >> "${TMPDIR}"/zram-device-list.new
274a277
>                                       test -f "${TMPDIR}"/zram-device-list.new && mv "${TMPDIR}"/zram-device-list.new "${TMPDIR}"/zram-device-list

mstormi · August 16, 2021, 9:52am

Please try installing again, we’ve fixed a bug.

narf27 · August 16, 2021, 8:31pm

after first reboot everything (well, at least the things i checked…) seems to work:

openhabian@ohab3:~ $ wget https://raw.githubusercontent.com/ecdye/zram-config/openHAB/zram-config
...
2021-08-16 22:27:27 (4.85 MB/s) - ‘zram-config’ saved [11021/11021]
openhabian@ohab3:~ $ diff zram-config /usr/local/sbin/zram-config

openhabian@ohab3:~ $ ls /var/log/openhab/
audit.log   events.log.1  openhab.log.1  openhab.log.3  Readme.txt
events.log  openhab.log   openhab.log.2  openhab.log.4

amanda backup ( triggered manually) went through.

grafana is now running

openhabian@ohab3:~ $ systemctl status grafana-server.service
● grafana-server.service - Grafana instance
   Loaded: loaded (/lib/systemd/system/grafana-server.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2021-08-16 22:23:10 CEST; 7min ago
     Docs: http://docs.grafana.org
 Main PID: 742 (grafana-server)
    Tasks: 12 (limit: 4915)
   CGroup: /system.slice/grafana-server.service
           └─742 /usr/sbin/grafana-server --config=/etc/grafana/grafana.ini --pidfile=/var/run/grafana/grafana-server.pid --packaging=deb cfg:default.paths.logs=/var/log/grafana cfg:default.paths.data=/var/lib/grafana cfg:default.paths.p

Aug 16 22:23:31 ohab3 grafana-server[742]: t=2021-08-16T22:23:31+0200 lvl=info msg="Path Provisioning" logger=settings path=/etc/grafana/provisioning
Aug 16 22:23:31 ohab3 grafana-server[742]: t=2021-08-16T22:23:31+0200 lvl=info msg="App mode production" logger=settings
Aug 16 22:23:31 ohab3 grafana-server[742]: t=2021-08-16T22:23:31+0200 lvl=info msg="Writing PID file" logger=server path=/var/run/grafana/grafana-server.pid pid=742
Aug 16 22:23:31 ohab3 grafana-server[742]: t=2021-08-16T22:23:31+0200 lvl=info msg="Connecting to DB" logger=sqlstore dbtype=sqlite3
Aug 16 22:23:31 ohab3 grafana-server[742]: t=2021-08-16T22:23:31+0200 lvl=info msg="Starting DB migrations" logger=migrator
Aug 16 22:23:31 ohab3 grafana-server[742]: t=2021-08-16T22:23:31+0200 lvl=info msg="migrations completed" logger=migrator performed=0 skipped=330 duration=2.879259ms
Aug 16 22:23:31 ohab3 grafana-server[742]: t=2021-08-16T22:23:31+0200 lvl=info msg="Starting plugin search" logger=plugins
Aug 16 22:23:32 ohab3 grafana-server[742]: t=2021-08-16T22:23:32+0200 lvl=info msg="Registering plugin" logger=plugins id=input
Aug 16 22:23:32 ohab3 grafana-server[742]: t=2021-08-16T22:23:32+0200 lvl=info msg="Live Push Gateway initialization" logger=live.push_http
Aug 16 22:23:32 ohab3 grafana-server[742]: t=2021-08-16T22:23:32+0200 lvl=info msg="HTTP Server Listen" logger=http.server address=[::]:3000 protocol=http subUrl= socket=

thank you guys!