- Platform information:
- Hardware: Rasperry Pi 3B+
- OS: Openhabian
- openHAB version: 2.3
- Issue of the topic: Boot.log stops at “Starting Terminate Plymouth Boot Screen” but system running normal
Hello community,
I am working with OH2 on Raspberry since about 4 weeks now, and since I have a kind of “stable” configuration, I started dealing with backups.
While trying to dig into some errors with raspi-backup (which I have running fine now), I noticed by coincidence that my boot.log always gets stuck at
[ OK ] Started openHAB 2 - empowering the smart home.
[ OK ] Started Frontail openHAB instance, r…chable at http://openHABianPi:9001.
Starting /etc/rc.local Compatibility...
[ OK ] Started Grafana instance.
Starting Permit User Sessions...
[ OK ] Started /etc/rc.local Compatibility.
[ OK ] Started Permit User Sessions.
Starting Hold until boot process finishes up...
Starting Terminate Plymouth Boot Screen...
Last timestamp of boot.log was
-rw-r--r-- 1 root root 5343 Dec 13 00:16 boot.log
The odd thing is: Everything is running normal. The syslog of this boot:
Dec 13 00:16:43 openHABianPi systemd[1]: Started Set the console keyboard layout.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target Local File Systems (Pre).
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Show Plymouth Boot Screen...
Dec 13 00:16:43 openHABianPi systemd[1]: Received SIGRTMIN+20 from PID 173 (plymouthd).
Dec 13 00:16:43 openHABianPi systemd[1]: Started Show Plymouth Boot Screen.
Dec 13 00:16:43 openHABianPi systemd[1]: Started Forward Password Requests to Plymouth Directory Watch.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target Encrypted Volumes.
Dec 13 00:16:43 openHABianPi systemd[1]: Found device /dev/serial1.
Dec 13 00:16:43 openHABianPi mtp-probe: checking bus 1, device 6: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.3"
Dec 13 00:16:43 openHABianPi mtp-probe: bus: 1, device: 6 was not an MTP device
Dec 13 00:16:43 openHABianPi systemd[1]: Found device /dev/disk/by-partuuid/d4be12d4-01.
Dec 13 00:16:43 openHABianPi systemd[1]: Starting File System Check on /dev/disk/by-partuuid/d4be12d4-01...
Dec 13 00:16:43 openHABianPi systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target Sound Card.
Dec 13 00:16:43 openHABianPi systemd-fsck[200]: fsck.fat 4.1 (2017-01-24)
Dec 13 00:16:43 openHABianPi systemd-fsck[200]: 0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
Dec 13 00:16:43 openHABianPi systemd-fsck[200]: Automatically removing dirty bit.
Dec 13 00:16:43 openHABianPi systemd-fsck[200]: Performing changes.
Dec 13 00:16:43 openHABianPi systemd-fsck[200]: /dev/mmcblk0p1: 183 files, 45106/84261 clusters
Dec 13 00:16:43 openHABianPi systemd[1]: Started File System Check on /dev/disk/by-partuuid/d4be12d4-01.
Dec 13 00:16:43 openHABianPi systemd[1]: Mounting /boot...
Dec 13 00:16:43 openHABianPi systemd[1]: Mounted /boot.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target Local File Systems.
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Create Volatile Files and Directories...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Preprocess NFS configuration...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Tell Plymouth To Write Out Runtime Data...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Set console font and keymap...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Raise network interfaces...
Dec 13 00:16:43 openHABianPi systemd[1]: Started Tell Plymouth To Write Out Runtime Data.
Dec 13 00:16:43 openHABianPi systemd[1]: Started Preprocess NFS configuration.
Dec 13 00:16:43 openHABianPi systemd[1]: Started Set console font and keymap.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target NFS client services.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target Remote File Systems (Pre).
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target Remote File Systems.
Dec 13 00:16:43 openHABianPi systemd[1]: Started Create Volatile Files and Directories.
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Network Time Synchronization...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Update UTMP about System Boot/Shutdown...
Dec 13 00:16:43 openHABianPi mtp-probe: checking bus 1, device 7: "/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1/1-1.1.1"
Dec 13 00:16:43 openHABianPi systemd[1]: Started Update UTMP about System Boot/Shutdown.
Dec 13 00:16:43 openHABianPi mtp-probe: bus: 1, device: 7 was not an MTP device
Dec 13 00:16:43 openHABianPi systemd-timesyncd[240]: System clock time unset or jumped backwards, restoring from recorded timestamp: Thu 2018-12-13 00:16:42 CET
Dec 13 00:16:43 openHABianPi systemd[1]: Time has been changed
Dec 13 00:16:43 openHABianPi systemd[1]: Started Network Time Synchronization.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target System Time Synchronized.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target System Initialization.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target Timers.
Dec 13 00:16:43 openHABianPi systemd[1]: Listening on D-Bus System Message Bus Socket.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target Sockets.
Dec 13 00:16:43 openHABianPi systemd[1]: Started CUPS Scheduler.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target Paths.
Dec 13 00:16:43 openHABianPi systemd[1]: Reached target Basic System.
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Save/Restore Sound Card State...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Login Service...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting LSB: Switch to ondemand cpu governor (unless shift key is pressed)...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting dhcpcd on all interfaces...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Disable WiFi if country not set...
Dec 13 00:16:43 openHABianPi systemd[1]: Started Regular background program processing daemon.
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Avahi mDNS/DNS-SD Stack...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting LSB: mosquitto MQTT v3.1 message broker...
Dec 13 00:16:43 openHABianPi cron[305]: (CRON) INFO (pidfile fd = 3)
Dec 13 00:16:43 openHABianPi systemd[1]: Started tuyaapi-mqtt.
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Configure Bluetooth Modems connected by UART...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting triggerhappy global hotkey daemon...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Internet superserver...
Dec 13 00:16:43 openHABianPi systemd[1]: Started D-Bus System Message Bus.
Dec 13 00:16:43 openHABianPi dhcpcd[301]: dev: loaded udev
Dec 13 00:16:43 openHABianPi wifi-country[302]: Wi-Fi is disabled because the country is not set
Dec 13 00:16:43 openHABianPi cron[305]: (CRON) INFO (Running @reboot jobs)
Dec 13 00:16:43 openHABianPi thd[312]: Found socket passed from systemd
Dec 13 00:16:43 openHABianPi avahi-daemon[306]: Found user 'avahi' (UID 108) and group 'avahi' (GID 112).
Dec 13 00:16:43 openHABianPi avahi-daemon[306]: Successfully dropped root privileges.
Dec 13 00:16:43 openHABianPi avahi-daemon[306]: avahi-daemon 0.6.32 starting up.
Dec 13 00:16:43 openHABianPi dhcpcd[301]: wlan0: starting wpa_supplicant
Dec 13 00:16:43 openHABianPi dhcpcd-run-hooks[359]: wlan0: starting wpa_supplicant
Dec 13 00:16:43 openHABianPi avahi-daemon[306]: Successfully called chroot().
Dec 13 00:16:43 openHABianPi avahi-daemon[306]: Successfully dropped remaining capabilities.
Dec 13 00:16:43 openHABianPi systemd[1]: Starting LSB: Start/stop sysstat's sadc...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting System Logging Service...
Dec 13 00:16:43 openHABianPi systemd[1]: Starting LSB: Autogenerate and use a swap file...
Dec 13 00:16:43 openHABianPi systemd[1]: Started CUPS Scheduler.
Dec 13 00:16:43 openHABianPi systemd[1]: Started triggerhappy global hotkey daemon.
Dec 13 00:16:43 openHABianPi systemd[1]: Started Internet superserver.
Dec 13 00:16:43 openHABianPi systemd[1]: Started Save/Restore Sound Card State.
Dec 13 00:16:43 openHABianPi avahi-daemon[306]: No service file found in /etc/avahi/services.
Dec 13 00:16:43 openHABianPi systemd[1]: Started Disable WiFi if country not set.
Dec 13 00:16:43 openHABianPi avahi-daemon[306]: Network interface enumeration completed.
Dec 13 00:16:43 openHABianPi avahi-daemon[306]: Server startup complete. Host name is openHABianPi.local. Local service cookie is 174737195.
Dec 13 00:16:43 openHABianPi systemd[1]: Started Raise network interfaces.
Dec 13 00:16:43 openHABianPi raspi-config[298]: Checking if shift key is held down:Error opening '/dev/input/event*': No such file or directory
Dec 13 00:16:43 openHABianPi dphys-swapfile[364]: Starting dphys-swapfile swapfile setup ...
Dec 13 00:16:43 openHABianPi raspi-config[298]: No. Switching to ondemand scaling governor.
Dec 13 00:16:43 openHABianPi systemd[1]: Started LSB: Switch to ondemand cpu governor (unless shift key is pressed).
Dec 13 00:16:43 openHABianPi systemd[1]: Started LSB: Start/stop sysstat's sadc.
Dec 13 00:16:43 openHABianPi systemd[1]: Started Avahi mDNS/DNS-SD Stack.
Dec 13 00:16:43 openHABianPi systemd[1]: Started Login Service.
Dec 13 00:16:43 openHABianPi systemd[1]: Started Make remote CUPS printers available locally.
Dec 13 00:16:43 openHABianPi systemd[1]: Starting Load/Save RF Kill Switch Status...
Dec 13 00:16:43 openHABianPi mosquitto[307]: Starting network daemon:: mosquitto.
Dec 13 00:16:43 openHABianPi systemd[1]: Started LSB: mosquitto MQTT v3.1 message broker.
Dec 13 00:16:43 openHABianPi liblogging-stdlog: [origin software="rsyslogd" swVersion="8.24.0" x-pid="363" x-info="http://www.rsyslog.com"] start
Dec 13 00:16:43 openHABianPi systemd[1]: Started System Logging Service.
Dec 13 00:16:43 openHABianPi kernel: [ 0.000000] Booting Linux on physical CPU 0x0
Dec 13 00:16:43 openHABianPi kernel: [ 0.000000] Linux version 4.14.79-v7+ (dc4@dc4-XPS13-9333) (gcc version 4.9.3 (crosstool-NG crosstool-ng-1.22.0-88-g8460611)) #1159 SMP Sun Nov 4 17:50:20 GMT 2018
Dec 13 00:16:43 openHABianPi kernel: [ 0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
Dec 13 00:16:43 openHABianPi kernel: [ 0.000000] CPU: div instructions available: patching division code
Dec 13 00:16:43 openHABianPi kernel: [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
Dec 13 00:16:43 openHABianPi kernel: [ 0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Plus Rev 1.3
allocations
Dec 13 00:16:43 openHABianPi kernel: [ 0.027518] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
Dec 13 00:16:43 openHABianPi kernel: [ 0.674976] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x805ea470
Dec 13 00:16:43 openHABianPi kernel: [ 0.676302] WARN::hcd_init_fiq:460: FIQ ASM at 0x805ea7d8 length 36
Dec 13 00:16:43 openHABianPi kernel: [ 0.677603] WARN::hcd_init_fiq:486: MPHI regs_base at 0xf0006000
extents:1 across:102396k SSFS
Dec 13 00:16:44 openHABianPi dphys-swapfile[364]: done.
Dec 13 00:16:44 openHABianPi systemd[1]: Started LSB: Autogenerate and use a swap file.
Dec 13 00:16:44 openHABianPi systemd[1]: Started Load/Save RF Kill Switch Status.
Dec 13 00:16:44 openHABianPi dhcpcd[301]: eth0: waiting for carrier
Dec 13 00:16:44 openHABianPi dhcpcd[301]: wlan0: if_up: Operation not possible due to RF-kill
Dec 13 00:16:44 openHABianPi dhcpcd[301]: wlan0: waiting for carrier
Dec 13 00:16:44 openHABianPi dhcpcd[301]: wlan0: carrier acquired
Dec 13 00:16:44 openHABianPi kernel: [ 6.444055] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
Dec 13 00:16:44 openHABianPi dhcpcd[301]: DUID 00:01:00:01:22:3b:12:e8:b8:27:eb:f2:4c:7a
Dec 13 00:16:44 openHABianPi dhcpcd[301]: wlan0: IAID eb:a7:19:2f
Dec 13 00:16:44 openHABianPi dhcpcd[301]: wlan0: adding address fe80::87c0:af98:9cca:b0c8
Dec 13 00:16:44 openHABianPi dhcpcd[301]: wlan0: carrier lost
Dec 13 00:16:44 openHABianPi dhcpcd[301]: wlan0: deleting address fe80::87c0:af98:9cca:b0c8
Dec 13 00:16:45 openHABianPi dhcpcd[301]: eth0: carrier acquired
Dec 13 00:16:45 openHABianPi kernel: [ 7.240138] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Dec 13 00:16:45 openHABianPi dhcpcd[301]: eth0: IAID eb:f2:4c:7a
Dec 13 00:16:45 openHABianPi dhcpcd[301]: eth0: adding address fe80::876f:2849:ff56:2acf
Dec 13 00:16:45 openHABianPi dhcpcd[301]: eth0: probing address 192.168.75.15/24
Dec 13 00:16:45 openHABianPi dhcpcd[301]: eth0: soliciting an IPv6 router
Dec 13 00:16:47 openHABianPi avahi-daemon[306]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::876f:2849:ff56:2acf.
Dec 13 00:16:47 openHABianPi avahi-daemon[306]: New relevant interface eth0.IPv6 for mDNS.
Dec 13 00:16:47 openHABianPi avahi-daemon[306]: Registering new address record for fe80::876f:2849:ff56:2acf on eth0.*.
Dec 13 00:16:49 openHABianPi dhcpcd[301]: eth0: using static address 192.168.75.15/24
Dec 13 00:16:49 openHABianPi avahi-daemon[306]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.75.15.
Dec 13 00:16:49 openHABianPi dhcpcd[301]: eth0: adding route to 192.168.75.0/24
Dec 13 00:16:49 openHABianPi avahi-daemon[306]: New relevant interface eth0.IPv4 for mDNS.
Dec 13 00:16:49 openHABianPi dhcpcd[301]: eth0: adding default route via 192.168.75.1
Dec 13 00:16:49 openHABianPi avahi-daemon[306]: Registering new address record for 192.168.75.15 on eth0.IPv4.
Dec 13 00:16:49 openHABianPi dhcpcd[301]: forked to background, child pid 496
Dec 13 00:16:49 openHABianPi systemd[1]: Started dhcpcd on all interfaces.
Dec 13 00:16:49 openHABianPi systemd[1]: Reached target Network.
Dec 13 00:16:49 openHABianPi systemd[1]: Starting OpenBSD Secure Shell server...
Dec 13 00:16:49 openHABianPi systemd[1]: Started Unattended Upgrades Shutdown.
Dec 13 00:16:49 openHABianPi systemd[1]: Reached target Network is Online.
Dec 13 00:16:49 openHABianPi systemd[1]: Started InfluxDB is an open-source, distributed, time series database.
Dec 13 00:16:49 openHABianPi systemd[1]: Starting LSB: exim Mail Transport Agent...
Dec 13 00:16:49 openHABianPi systemd[1]: Starting Automounts filesystems on demand...
Dec 13 00:16:50 openHABianPi systemd[1]: Starting Samba NMB Daemon...
Dec 13 00:16:50 openHABianPi systemd[1]: Started openHAB 2 - empowering the smart home.
Dec 13 00:16:50 openHABianPi systemd[1]: Started Frontail openHAB instance, reachable at http://openHABianPi:9001.
Dec 13 00:16:50 openHABianPi systemd[1]: Starting /etc/rc.local Compatibility...
Dec 13 00:16:50 openHABianPi systemd[1]: Started Grafana instance.
Dec 13 00:16:50 openHABianPi systemd[1]: Starting Permit User Sessions...
Dec 13 00:16:50 openHABianPi systemd[1]: Started /etc/rc.local Compatibility.
Dec 13 00:16:50 openHABianPi systemd[1]: Started Permit User Sessions.
Dec 13 00:16:50 openHABianPi systemd[1]: Starting Hold until boot process finishes up...
Dec 13 00:16:50 openHABianPi systemd[1]: Starting Terminate Plymouth Boot Screen...
Dec 13 00:16:50 openHABianPi systemd[1]: Received SIGRTMIN+21 from PID 173 (plymouthd).
Dec 13 00:16:50 openHABianPi systemd[1]: Started Terminate Plymouth Boot Screen.
Dec 13 00:16:50 openHABianPi systemd[1]: Started Hold until boot process finishes up.
Dec 13 00:16:50 openHABianPi systemd[1]: Started Getty on tty1.
Dec 13 00:16:50 openHABianPi systemd[1]: Reached target Login Prompts.
Dec 13 00:16:50 openHABianPi systemd[1]: Started Load/Save RF Kill Switch Status.
Dec 13 00:16:50 openHABianPi systemd[1]: Starting Bluetooth service...
Dec 13 00:16:50 openHABianPi systemd[1]: Created slice system-bthelper.slice.
Dec 13 00:16:50 openHABianPi systemd[1]: Started OpenBSD Secure Shell server.
Dec 13 00:16:50 openHABianPi bluetoothd[695]: Bluetooth daemon 5.43
Dec 13 00:16:50 openHABianPi systemd[1]: Started Bluetooth service.
Dec 13 00:16:50 openHABianPi systemd[1]: Reached target Bluetooth.
Dec 13 00:16:50 openHABianPi systemd[1]: Started Raspberry Pi bluetooth helper.
Dec 13 00:16:51 openHABianPi systemd[1]: Started Hostname Service.
Dec 13 00:16:51 openHABianPi systemd[1]: Started Automounts filesystems on demand.
Dec 13 00:16:52 openHABianPi exim4[499]: Starting MTA: exim4.
Dec 13 00:16:52 openHABianPi systemd[1]: Started LSB: exim Mail Transport Agent.
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Starting Grafana" logger=server version=5.1.4 commit=a5fe24f compiled=2018-06-19T12:54:57+0200
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Config loaded from" logger=settings file=/usr/share/grafana/conf/defaults.ini
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Config loaded from" logger=settings file=/etc/grafana/grafana.ini
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.data=/var/lib/grafana"
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.logs=/var/log/grafana"
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.plugins=/var/lib/grafana/plugins"
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Config overridden from command line" logger=settings arg="default.paths.provisioning=/etc/grafana/provisioning"
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Path Home" logger=settings path=/usr/share/grafana
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Path Data" logger=settings path=/var/lib/grafana
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Path Logs" logger=settings path=/var/log/grafana
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Path Plugins" logger=settings path=/var/lib/grafana/plugins
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Path Provisioning" logger=settings path=/etc/grafana/provisioning
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="App mode production" logger=settings
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Writing PID file" logger=server path=/var/run/grafana/grafana-server.pid pid=507
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Initializing DB" logger=sqlstore dbtype=sqlite3
Dec 13 00:16:52 openHABianPi grafana-server[507]: t=2018-12-13T00:16:52+0100 lvl=info msg="Starting DB migration" logger=migrator
Dec 13 00:16:53 openHABianPi grafana-server[507]: t=2018-12-13T00:16:53+0100 lvl=info msg="Executing migration" logger=migrator id="copy data account to org"
Dec 13 00:16:53 openHABianPi grafana-server[507]: t=2018-12-13T00:16:53+0100 lvl=info msg="Skipping migration condition not fulfilled" logger=migrator id="copy data account to org"
Dec 13 00:16:53 openHABianPi grafana-server[507]: t=2018-12-13T00:16:53+0100 lvl=info msg="Executing migration" logger=migrator id="copy data account_user to org_user"
Dec 13 00:16:53 openHABianPi grafana-server[507]: t=2018-12-13T00:16:53+0100 lvl=info msg="Skipping migration condition not fulfilled" logger=migrator id="copy data account_user to org_user"
Dec 13 00:16:53 openHABianPi grafana-server[507]: t=2018-12-13T00:16:53+0100 lvl=info msg="Starting plugin search" logger=plugins
Dec 13 00:16:53 openHABianPi systemd[1]: nmbd.service: Supervising process 894 which is not our child. We'll most likely not notice when it exits.
Dec 13 00:16:53 openHABianPi systemd[1]: Started Samba NMB Daemon.
Dec 13 00:16:53 openHABianPi systemd[1]: Starting Samba SMB Daemon...
Dec 13 00:16:53 openHABianPi grafana-server[507]: t=2018-12-13T00:16:53+0100 lvl=info msg="Initializing Alerting" logger=alerting.engine
Dec 13 00:16:53 openHABianPi grafana-server[507]: t=2018-12-13T00:16:53+0100 lvl=info msg="Initializing CleanUpService" logger=cleanup
Dec 13 00:16:53 openHABianPi systemd[1]: smbd.service: Supervising process 900 which is not our child. We'll most likely not notice when it exits.
Dec 13 00:16:53 openHABianPi grafana-server[507]: t=2018-12-13T00:16:53+0100 lvl=info msg="Initializing Stream Manager"
Dec 13 00:16:53 openHABianPi grafana-server[507]: t=2018-12-13T00:16:53+0100 lvl=info msg="Initializing HTTP Server" logger=http.server address=0.0.0.0:3000 protocol=http subUrl= socket=
Dec 13 00:16:53 openHABianPi systemd[1]: Started Samba SMB Daemon.
Dec 13 00:16:53 openHABianPi systemd[1]: Reached target Multi-User System.
Dec 13 00:16:53 openHABianPi systemd[1]: Reached target Graphical Interface.
Dec 13 00:16:53 openHABianPi systemd[1]: Starting Update UTMP about System Runlevel Changes...
Dec 13 00:16:54 openHABianPi systemd[1]: Started Update UTMP about System Runlevel Changes.
Dec 13 00:16:54 openHABianPi systemd[1]: Startup finished in 1.902s (kernel) + 14.135s (userspace) = 16.037s.
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.348866Z lvl=info msg="InfluxDB starting" log_id=0CLBBNo0000 version=1.7.1 branch=1.7 commit=cb03c542a4054f0f4d3dc13919d31c456bdb5c39
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.348972Z lvl=info msg="Go runtime" log_id=0CLBBNo0000 version=go1.11 maxprocs=4
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.482086Z lvl=info msg="Using data dir" log_id=0CLBBNo0000 service=store path=/var/lib/influxdb/data
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.482334Z lvl=info msg="Compaction settings" log_id=0CLBBNo0000 service=store max_concurrent_compactions=2 throughput_bytes_per_second=50331648 throughput_bytes_per_second_burst=50331648
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.482416Z lvl=info msg="Open store (start)" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open op_event=start
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.623512Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/_internal/monitor/23/000000006-000000002.tsm id=0 duration=57.425ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.618082Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/_internal/monitor/22/000000005-000000002.tsm id=0 duration=50.906ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.632268Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/_internal/monitor/24/000000006-000000002.tsm id=0 duration=65.093ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.679359Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/_internal/monitor/27/000000004-000000002.tsm id=0 duration=74.181ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.680039Z lvl=info msg="Reading file" log_id=0CLBBNo0000 engine=tsm1 service=cacheloader path=/var/lib/influxdb/wal/_internal/monitor/27/_00013.wal size=21817366
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.757037Z lvl=info msg="Opened shard" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open index_version=inmem path=/var/lib/influxdb/data/_internal/monitor/23 duration=245.892ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.768116Z lvl=info msg="Opened shard" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open index_version=inmem path=/var/lib/influxdb/data/_internal/monitor/24 duration=256.976ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.792157Z lvl=info msg="Opened shard" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open index_version=inmem path=/var/lib/influxdb/data/_internal/monitor/22 duration=281.048ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.803298Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/_internal/monitor/19/000000005-000000002.tsm id=0 duration=35.938ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.832219Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/_internal/monitor/20/000000004-000000002.tsm id=0 duration=53.853ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.844581Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/_internal/monitor/21/000000005-000000002.tsm id=0 duration=35.338ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.867313Z lvl=info msg="Opened shard" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open index_version=inmem path=/var/lib/influxdb/data/_internal/monitor/19 duration=107.526ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.901829Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/_internal/monitor/26/000000004-000000002.tsm id=0 duration=28.949ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.914215Z lvl=info msg="Opened shard" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open index_version=inmem path=/var/lib/influxdb/data/_internal/monitor/21 duration=121.746ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.920010Z lvl=info msg="Opened shard" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open index_version=inmem path=/var/lib/influxdb/data/_internal/monitor/20 duration=151.690ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.932352Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/openhab_db/autogen/9/000000001-000000001.tsm id=0 duration=8.958ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.938332Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/openhab_db/autogen/2/000000084-000000002.tsm id=0 duration=9.874ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.960375Z lvl=info msg="Opened shard" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open index_version=inmem path=/var/lib/influxdb/data/_internal/monitor/26 duration=92.692ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.981114Z lvl=info msg="Opened shard" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open index_version=inmem path=/var/lib/influxdb/data/openhab_db/autogen/2 duration=60.783ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.983086Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/openhab_db/autogen/25/000000001-000000001.tsm id=0 duration=8.316ms
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.983831Z lvl=info msg="Reading file" log_id=0CLBBNo0000 engine=tsm1 service=cacheloader path=/var/lib/influxdb/wal/openhab_db/autogen/25/_00001.wal size=465422
Dec 13 00:16:54 openHABianPi influxd[498]: ts=2018-12-12T23:16:54.991940Z lvl=info msg="Opened shard" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open index_version=inmem path=/var/lib/influxdb/data/openhab_db/autogen/9 duration=77.477ms
Dec 13 00:16:55 openHABianPi influxd[498]: ts=2018-12-12T23:16:55.000914Z lvl=info msg="Opened file" log_id=0CLBBNo0000 engine=tsm1 service=filestore path=/var/lib/influxdb/data/openhab_db/autogen/17/000000001-000000001.tsm id=0 duration=7.001ms
Dec 13 00:16:55 openHABianPi influxd[498]: ts=2018-12-12T23:16:55.041472Z lvl=info msg="Opened shard" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open index_version=inmem path=/var/lib/influxdb/data/openhab_db/autogen/17 duration=59.989ms
Dec 13 00:16:55 openHABianPi influxd[498]: ts=2018-12-12T23:16:55.203341Z lvl=info msg="Opened shard" log_id=0CLBBNo0000 service=store trace_id=0CLBBOKW000 op_name=tsdb_open index_version=inmem path=/var/lib/influxdb/data/openhab_db/autogen/25 duration=242.710ms
Dec 13 00:16:59 openHABianPi dhcpcd[496]: eth0: no IPv6 Routers available
Dec 13 00:17:01 openHABianPi CRON[995]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Dec 13 00:17:01 openHABianPi systemd[1]: Created slice User Slice of openhabian.
Dec 13 00:17:01 openHABianPi systemd[1]: Starting User Manager for UID 1000...
Dec 13 00:17:01 openHABianPi systemd[1]: Started Session c1 of user openhabian.
Dec 13 00:17:01 openHABianPi systemd[1007]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Dec 13 00:17:01 openHABianPi systemd[1007]: Reached target Timers.
Dec 13 00:17:01 openHABianPi systemd[1007]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Dec 13 00:17:01 openHABianPi systemd[1007]: Listening on GnuPG cryptographic agent (access for web browsers).
Dec 13 00:17:01 openHABianPi systemd[1007]: Reached target Paths.
Dec 13 00:17:01 openHABianPi systemd[1007]: Listening on GnuPG cryptographic agent and passphrase cache.
Dec 13 00:17:01 openHABianPi systemd[1007]: Listening on GnuPG network certificate management daemon.
Dec 13 00:17:01 openHABianPi systemd[1007]: Reached target Sockets.
Dec 13 00:17:01 openHABianPi systemd[1007]: Reached target Basic System.
Dec 13 00:17:01 openHABianPi systemd[1007]: Reached target Default.
Dec 13 00:17:01 openHABianPi systemd[1007]: Startup finished in 72ms.
In openhab.log I only find this warning:
2018-12-13 00:15:47.806 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception
java.lang.NoSuchFieldError: DOBSON_UNIT
at org.openhab.binding.openuv.internal.handler.OpenUVReportHandler.updateChannel(OpenUVReportHandler.java:183) ~[?:?]
at org.openhab.binding.openuv.internal.handler.OpenUVReportHandler.updateChannels(OpenUVReportHandler.java:128) ~[?:?]
at org.openhab.binding.openuv.internal.handler.OpenUVReportHandler.lambda$1(OpenUVReportHandler.java:118) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
And like this:
2018-12-13 00:15:56.324 [WARN ] [eclipse.jetty.servlet.ServletHandler] -
javax.servlet.ServletException: A MultiException has 1 exceptions. They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_3,4,23716590) has been shut down
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:489) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) [167:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) [15:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:848) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:584) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [84:org.eclipse.jetty.server:9.3.21.v20170918]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [82:org.eclipse.jetty.security:9.3.21.v20170918]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226) [84:org.eclipse.jetty.server:9.3.21.v20170918]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180) [84:org.eclipse.jetty.server:9.3.21.v20170918]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:284) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512) [85:org.eclipse.jetty.servlet:9.3.21.v20170918]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185) [84:org.eclipse.jetty.server:9.3.21.v20170918]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112) [84:org.eclipse.jetty.server:9.3.21.v20170918]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [84:org.eclipse.jetty.server:9.3.21.v20170918]
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [183:org.ops4j.pax.web.pax-web-jetty:6.0.9]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134) [84:org.eclipse.jetty.server:9.3.21.v20170918]
at org.eclipse.jetty.server.Server.handle(Server.java:534) [84:org.eclipse.jetty.server:9.3.21.v20170918]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:333) [84:org.eclipse.jetty.server:9.3.21.v20170918]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251) [84:org.eclipse.jetty.server:9.3.21.v20170918]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283) [76:org.eclipse.jetty.io:9.3.21.v20170918]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108) [76:org.eclipse.jetty.io:9.3.21.v20170918]
at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93) [76:org.eclipse.jetty.io:9.3.21.v20170918]
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303) [87:org.eclipse.jetty.util:9.3.21.v20170918]
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148) [87:org.eclipse.jetty.util:9.3.21.v20170918]
at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136) [87:org.eclipse.jetty.util:9.3.21.v20170918]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671) [87:org.eclipse.jetty.util:9.3.21.v20170918]
at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589) [87:org.eclipse.jetty.util:9.3.21.v20170918]
at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: org.glassfish.hk2.api.MultiException: A MultiException has 1 exceptions. They are:
1. java.lang.IllegalStateException: ServiceLocatorImpl(__HK2_Generated_3,4,23716590) has been shut down
The really odd thing is: In syslog the message about plymouth also appears around 00:16:50, but as syslog continues, boot.log stops… And everything is up and running normal. If I did not check boot.log by coincidence, I would never found out that boot is halting, since I always connect headless by ssh’ing.
Edit:
I just tried booting with a “old” image (I started using OpenHab with a old 8GB SD-Card) from November 20th were I did no modifications to openhabian itself except installing automount, it shows the same symptoms.
Any ideas what could be wrong?
