#1199 Issue `closed`: sysinit.service does not start correctly¶

Labels: support / question, fixed / solved / done

proura opened issue at 2017-02-14 07:14:¶

Relax-and-Recover (rear) Issue Template¶

Please fill in the following items before submitting a new issue (quick response is not guaranteed with free support):

rear version (/usr/sbin/rear -V):
Test1: Relax-and-Recover 2.00 / Git
OS version (cat /etc/rear/os.conf or lsb_release -a):
Test1:
No LSB modules are available.
Distributor ID: Debian
Description: Debian GNU/Linux 8.7 (jessie)
Release: 8.7
Codename: jessie
rear configuration files (cat /etc/rear/site.conf or cat /etc/rear/local.conf):

DRLM_MANAGED=y

--------DRLM rear-deb0.cfg file--------
CLI_NAME=rear-deb8
SRV_NET_IP=192.168.1.34

OUTPUT=PXE
OUTPUT_PREFIX=$OUTPUT
OUTPUT_PREFIX_PXE=rear-deb8/$OUTPUT
OUTPUT_URL=nfs://192.168.1.34/var/lib/drlm/store/rear-deb8
BACKUP=NETFS
NETFS_PREFIX=BKP
BACKUP_URL=nfs://192.168.1.34/var/lib/drlm/store/rear-deb8
SSH_ROOT_PASSWORD=drlm
USE_DHCLIENT=y

Are you using legacy BIOS or UEFI boot?
BIOS - VirtualBox Network boot PXE
Brief description of the issue:
After boot from network and do the root login the system doesn't have the correct keyboard layout, doesn't get automatically the ip with dhclient and other failures.
Also tryed with Centos7 and ReaR 1.17.2 and happens the same error.
Work-around, if any:
I have found and error when sysinit.service is starting , but deleting the line StandartInput=tty or adding TTYPath=/dev/tty inside the sysinit.service works correctly in boths testings.

jsmeix commented at 2017-02-15 11:22:¶

@didacog
FYI because this one contains "DRLM_MANAGED=y"

Regarding the actual issue

deleting the line StandartInput=tty
or adding TTYPath=/dev/tty
inside the sysinit.service works correctly

According to
git log -p --follow usr/share/rear/skel/default/usr/lib/systemd/system/sysinit.service
the "StandardInput=tty" line in
usr/share/rear/skel/default/usr/lib/systemd/system/sysinit.service
was set via
https://github.com/rear/rear/commit/dc49c6801a1536bbd02b58a54a4e09b15ba258fc

As far as I see
usr/share/rear/skel/default/usr/lib/systemd/system/sysinit.service
is a static file that is used "as is" in the ReaR recovery system
so that it is currently the only possible way to adapt it as needed
when things therein do not work.

didacog commented at 2017-02-15 11:44:¶

@jsmeix
Yes the issue was opened by @proura (DRLM Team) because we have this issue, is not only a DRLM problem I guess, should be a problem for, at least, any PXE use case.

Maybe adding TTYPath=/dev/tty to the sysinit.service will keep backward compatibility and doesn't broke anything.

If you are agree, we can send a pull request for it if needed.

PD: for you to know of all DRLM team members for future issues and/or contributions to ReaR.

Ruben Carbonell: @krbu
Pau Roura: @proura
and me ;)

Regards,

gdha commented at 2017-02-15 12:31:¶

I have been using PXE boot method during the last couple of months on a daily basis, and never had this issue. Strange. I'll test it out myself.

gdha commented at 2017-02-15 14:35:¶

@proura @didacog I've tested both methods:

deleting the line StandartInput=tty or adding TTYPath=/dev/tty inside the sysinit.service works correctly in both testing.

and I'm sorry to say both methods seem to fail within a centos 7 vm.

jsmeix commented at 2017-02-15 15:05:¶

Perhaps a stupid question (I am not at all a systemd expert):
Is
usr/share/rear/skel/default/usr/lib/systemd/system/sysinit.service
only used in case of PXE boot
or isn't that in general used to run etc/scripts/system-setup
during ReaR recovery system startup?

If
usr/share/rear/skel/default/usr/lib/systemd/system/sysinit.service
is always used during ReaR recovery system startup,
then it always also worked for me
(I never used PXE boot - I always boot from the ISO)
so that perhaps something special is different on
Debian GNU/Linux 8.7 (jessie) why it does not
work there?

proura commented at 2017-02-15 15:17:¶

@gdha I have now tried in Centos7 VM and works fine for me. I write my steps below versions info.

1. rear version (/usr/sbin/rear -V):

RESCUE localhost:~ # /usr/sbin/rear -V
Relax-and-Recover 1.17.2 / Git

OS version (cat /etc/rear/os.conf or lsb_release -a):

RESCUE localhost:~ # cat /etc/rear/os.conf
OS_VENDOR=RedHatEnterpriseServer
OS_VERSION=7
ARCH='Linux-i386'
OS='GNU/Linux'
OS_VERSION='7'
OS_VENDOR='RedHatEnterpriseServer'
OS_VENDOR_VERSION='RedHatEnterpriseServer/7'
OS_VENDOR_ARCH='RedHatEnterpriseServer/i386'

Step by step solution:

RESCUE localhost:~ # systemctl start sysinit.service
Job for sysinit.service failed because the control process exited with error code. See "systemctl status sysinit.service" and "journalctl -xe" for details.

RESCUE localhost:~ # vi /usr/lib/systemd/system/sysinit.service

[Unit]
Description=Initialize Rescue System
After=systemd-udevd.service

[Service]
Type=oneshot
ExecStart=/etc/scripts/system-setup

RESCUE localhost:~ # systemctl daemon-reload
RESCUE localhost:~ # systemctl start sysinit.service
RESCUE localhost:~ # systemctl status sysinit.service
● sysinit.service - Initialize Rescue System
Loaded: loaded (/usr/lib/systemd/system/sysinit.service; static; vendor preset: enabled)
Active: inactive (dead) since Wed 2017-02-15 15:07:52 UTC; 1min 36s ago
Main PID: 245 (code=exited, status=0/SUCCESS)

didacog commented at 2017-02-15 15:51:¶

@gdha
I've also tested the steps @proura said with centOS7 VM with rear-2.0.
Removing StandardInput=tty works, if not, fails trying to start system-setup from sysinit.service.

gdha commented at 2017-02-15 16:49:¶

@proura @didacog it might behave different with libvirt then with virtualbox? Very weird. Will try it tomorrow on vb

didacog commented at 2017-02-15 17:13:¶

Could be VBox or maybe something working different with our GRUB2 based NetBoot. We will do more tests to find the root cause, that seems has different results depending on the environment.

At least now we know that is working for you and maybe is something in our env that is causing this issue with tty stdin. :)

didacog commented at 2017-02-16 08:59:¶

@gdha we've tested different things and seems that is VBox and nothing about our GRUB2 netboot. We'll wait for your tests on VBox to confirm this.

jsmeix commented at 2017-02-16 09:00:¶

@proura
and what do you see when you do

See "systemctl status sysinit.service" and "journalctl -xe" for details.

?

We need the reason why sysinit.service fails.

Only a blind shot in the dark:
In
https://alan-mushi.github.io/2014/10/26/execute-an-interactive-script-at-boot-with-systemd.html
I found

[Unit]
Description=Simple interactive dialog window
After=getty@tty2.service

[Service]
Type=oneshot
ExecStart=/usr/bin/dialog-hello.sh
StandardInput=tty
TTYPath=/dev/tty2
TTYReset=yes
TTYVHangup=yes

[Install]
WantedBy=default.target

therein I noted the "After=getty@tty2.service"
which leads to my blind guess that sysinit.service might fail
because whatever precondition(s) is/are not (yet) fulfilled
at the time when sysinit.service is run?

In particular because since udev one can no longer rely on
"things to be just there" because since udev device nodes
appear at arbitrary time (i.e. with arbitrary delays), cf.
https://github.com/rear/rear/issues/791

proura commented at 2017-02-17 09:52:¶

@jsmeix I will take a look arround you guess, the outputs of systemctl status sysinit.service and journalctl -xn are the next ones:

RESCUE rear-deb8:~ # systemctl status sysinit.service
● sysinit.service - Initialize Rescue System
Loaded: loaded (/usr/lib/systemd/system/sysinit.service; static)
Active: failed (Result: exit-code) since Fri 2017-02-17 10:17:54 CET; 2min 7s ago
Process: 162 ExecStart=/etc/scripts/system-setup (code=exited, status=208/STDIN)
Main PID: 162 (code=exited, status=208/STDIN)

RESCUE rear-deb8:~ # journalctl -xn
-- Logs begin at Fri 2017-02-17 10:16:21 CET, end at Fri 2017-02-17 10:22:23 CET. --
Feb 17 10:22:23 rear-deb8 systemd[1]: Failed to start Initialize Rescue System.
Feb 17 10:22:23 rear-deb8 systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1 interfacFeb 17 10:22:23 rear-deb8 systemd[1]: Unit sysinit.service entered failed state.
Feb 17 10:22:23 rear-deb8 systemd[1]: sysinit.service: cgroup is empty
Feb 17 10:22:23 rear-deb8 systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/sysFeb 17 10:22:23 rear-deb8 systemd[1]: Sent message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/unit/sysFeb 17 10:22:23 rear-deb8 systemd[1]: Got disconnect on private connection.
Feb 17 10:22:23 rear-deb8 systemd[1]: Accepted new private connection.
Feb 17 10:22:23 rear-deb8 systemd[1]: Got message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/agent intFeb 17 10:22:23 rear-deb8 systemd[1]: Got disconnect on private connection.

@gdha @didacog I have tried to run the same example in KVM and it works perfectly, so the problem is something related to VirtualBox environment.

proura commented at 2017-02-17 10:17:¶

Sorry @jsmeix, before I have attached the journalctl -xn output, there is the journalctl -xe:

RESCUE rear-deb8:~ # journalctl -xe
Feb 17 11:07:41 rear-deb8 systemd[1]: Child 37 (boot) died (code=exited, status=0/SUCCESS)
Feb 17 11:07:41 rear-deb8 systemd[1]: Child 37 belongs to rear-boot-helper.service
Feb 17 11:07:41 rear-deb8 systemd[1]: rear-boot-helper.service: main process exited, code=exited, status=0/SUCCESS
Feb 17 11:07:41 rear-deb8 systemd[1]: rear-boot-helper.service changed start -> dead
Feb 17 11:07:41 rear-deb8 systemd[1]: Job rear-boot-helper.service/start finished, result=done
Feb 17 11:07:41 rear-deb8 systemd[1]: Started Relax-and-Recover boot script.
Feb 17 11:07:40 localhost systemd[1]: Reached target Sockets.
Feb 17 11:07:40 localhost systemd[44]: Executing: /usr/lib/systemd/systemd-udevd
Feb 17 11:07:40 localhost systemd[1]: Got notification message for unit systemd-udevd.service
Feb 17 11:07:40 localhost systemd[1]: systemd-udevd.service: Got notification message from PID 44 (READY=1...)
Feb 17 11:07:40 localhost systemd[1]: systemd-udevd.service: got READY=1
Feb 17 11:07:40 localhost systemd[1]: systemd-udevd.service changed start -> running
Feb 17 11:07:40 localhost systemd[1]: Job systemd-udevd.service/start finished, result=done
Feb 17 11:07:40 localhost systemd[45]: Executing: /usr/bin/udevadm trigger --type=subsystems --action=add
Feb 17 11:07:40 localhost systemd[1]: Started udev Kernel Device Manager.
Feb 17 11:07:40 localhost systemd[1]: systemd-udevd-kernel.socket changed listening -> running
Feb 17 11:07:40 localhost systemd[1]: Job systemd-udevd-control.socket/start finished, result=done
Feb 17 11:07:40 localhost systemd[1]: Listening on udev Control Socket.
Feb 17 11:07:40 localhost systemd[1]: ConditionCapability=CAP_MKNOD succeeded for systemd-udevd.service.
Feb 17 11:07:40 localhost systemd[1]: Starting udev Kernel Device Manager...
Feb 17 11:07:40 localhost systemd[1]: About to execute: /usr/lib/systemd/systemd-udevd
Feb 17 11:07:40 localhost systemd[1]: Forked /usr/lib/systemd/systemd-udevd as 44
Feb 17 11:07:40 localhost systemd[1]: systemd-udevd.service changed dead -> start
Feb 17 11:07:40 localhost systemd[1]: Starting udev Coldplug all Devices...
Feb 17 11:07:40 localhost systemd[1]: About to execute: /usr/bin/udevadm trigger --type=subsystems --action=add
Feb 17 11:07:40 localhost systemd[1]: Forked /usr/bin/udevadm as 45
Feb 17 11:07:40 localhost systemd[1]: systemd-udev-trigger.service changed dead -> start
Feb 17 11:07:40 localhost systemd[1]: Starting System Initialization.
Feb 17 11:07:40 localhost systemd[1]: sysinit.target changed dead -> active
Feb 17 11:07:40 localhost systemd[1]: Job sysinit.target/start finished, result=done
Feb 17 11:07:40 localhost systemd[1]: Reached target System Initialization.
Feb 17 11:07:40 localhost systemd[1]: Starting D-Bus System Message Bus Socket.
Feb 17 11:07:40 localhost systemd[1]: dbus.socket changed dead -> listening
Feb 17 11:07:40 localhost systemd[1]: Job dbus.socket/start finished, result=done
Feb 17 11:07:40 localhost systemd[1]: Listening on D-Bus System Message Bus Socket.
Feb 17 11:07:40 localhost systemd[1]: Starting Sockets.
Feb 17 11:07:40 localhost systemd[1]: sockets.target changed dead -> active
Feb 17 11:07:40 localhost systemd[1]: Job sockets.target/start finished, result=done
Feb 17 11:07:40 localhost systemd[1]: Reached target Sockets.
Feb 17 11:07:40 localhost systemd[44]: Executing: /usr/lib/systemd/systemd-udevd
Feb 17 11:07:40 localhost systemd[1]: Got notification message for unit systemd-udevd.service
Feb 17 11:07:40 localhost systemd[1]: systemd-udevd.service: Got notification message from PID 44 (READY=1...)
Feb 17 11:07:40 localhost systemd[1]: systemd-udevd.service: got READY=1
Feb 17 11:07:40 localhost systemd[1]: systemd-udevd.service changed start -> running
Feb 17 11:07:40 localhost systemd[1]: Job systemd-udevd.service/start finished, result=done
Feb 17 11:07:40 localhost systemd[45]: Executing: /usr/bin/udevadm trigger --type=subsystems --action=add
Feb 17 11:07:40 localhost systemd[1]: Started udev Kernel Device Manager.
Feb 17 11:07:40 localhost systemd[1]: systemd-udevd-kernel.socket changed listening -> running
Feb 17 11:07:40 localhost systemd[1]: systemd-udevd-control.socket changed listening -> running
Feb 17 11:07:40 localhost systemd[1]: Got notification message for unit systemd-udevd.service
Feb 17 11:07:40 localhost systemd[1]: systemd-udevd.service: Got notification message from PID 44 (READY=1...)
Feb 17 11:07:40 localhost systemd[1]: Received SIGCHLD from PID 45 (udevadm).
Feb 17 11:07:40 localhost systemd[1]: Child 45 (udevadm) died (code=exited, status=0/SUCCESS)
Feb 17 11:07:40 localhost systemd[1]: Child 45 belongs to systemd-udev-trigger.service
Feb 17 11:07:40 localhost systemd[1]: systemd-udev-trigger.service: main process exited, code=exited, status=0/SUCCESS
Feb 17 11:07:40 localhost systemd[1]: systemd-udev-trigger.service running next main command for state start
Feb 17 11:07:40 localhost systemd[1]: About to execute: /usr/bin/udevadm trigger --type=devices --action=add
Feb 17 11:07:40 localhost systemd[1]: Forked /usr/bin/udevadm as 51
Feb 17 11:07:40 localhost systemd[1]: Starting Basic System.
Feb 17 11:07:40 localhost systemd[1]: basic.target changed dead -> active
Feb 17 11:07:40 localhost systemd[1]: Job basic.target/start finished, result=done
Feb 17 11:07:40 localhost systemd[1]: Reached target Basic System.
Feb 17 11:07:40 localhost systemd[1]: Starting Initialize Rescue System...
Feb 17 11:07:40 localhost systemd[1]: About to execute: /etc/scripts/system-setup
Feb 17 11:07:40 localhost systemd[1]: Forked /etc/scripts/system-setup as 53
Feb 17 11:07:40 localhost systemd[1]: sysinit.service changed dead -> start
Feb 17 11:07:40 localhost kernel: random: sshd: uninitialized urandom read (32 bytes read, 2 bits of entropy available)
Feb 17 11:07:40 localhost systemd-udevd[44]: starting version 215
Feb 17 11:07:40 localhost systemd[51]: Executing: /usr/bin/udevadm trigger --type=devices --action=add
Feb 17 11:07:40 localhost systemd[53]: Failed at step STDIN spawning /etc/scripts/system-setup: Inappropriate ioctl for device
Feb 17 11:07:40 localhost systemd[1]: Received SIGCHLD from PID 53 ((em-setup)).
Feb 17 11:07:40 localhost systemd[1]: Child 53 ((em-setup)) died (code=exited, status=208/STDIN)
Feb 17 11:07:40 localhost systemd[1]: Child 53 belongs to sysinit.service
Feb 17 11:07:40 localhost systemd[1]: sysinit.service: main process exited, code=exited, status=208/STDIN
Feb 17 11:07:40 localhost systemd[1]: sysinit.service changed start -> failed
Feb 17 11:07:40 localhost systemd[1]: Job sysinit.service/start finished, result=failed
Feb 17 11:07:40 localhost systemd[1]: Failed to start Initialize Rescue System.
Feb 17 11:07:40 localhost systemd[1]: Unit sysinit.service entered failed state.
Feb 17 11:07:40 localhost systemd[1]: sysinit.service: cgroup is empty
Feb 17 11:07:40 localhost systemd[1]: Accepted new private connection.
Feb 17 11:07:40 localhost systemd[1]: Got message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/agent interface=org.freedesktop.systemd1.Agent member=Feb 17 11:07:40 localhost systemd[1]: Accepted new private connection.
Feb 17 11:07:40 localhost systemd[1]: Got disconnect on private connection.
Feb 17 11:07:40 localhost systemd[1]: Got message type=signal sender=n/a destination=n/a object=/org/freedesktop/systemd1/agent interface=org.freedesktop.systemd1.Agent member=Feb 17 11:07:40 localhost systemd[1]: Got disconnect on private connection.
Feb 17 11:07:40 localhost systemd[1]: Starting Getty on tty1...
Feb 17 11:07:40 localhost systemd[1]: About to execute: /sbin/agetty tty1 38400
Feb 17 11:07:40 localhost systemd[1]: Forked /sbin/agetty as 67
Feb 17 11:07:40 localhost systemd[1]: getty@tty1.service changed dead -> running
Feb 17 11:07:40 localhost systemd[1]: Job getty@tty1.service/start finished, result=done
Feb 17 11:07:40 localhost systemd[1]: Started Getty on tty1.
Feb 17 11:07:40 localhost systemd[1]: Starting Getty on tty2...
Feb 17 11:07:40 localhost systemd[1]: About to execute: /sbin/agetty tty2 38400
Feb 17 11:07:40 localhost systemd[1]: Forked /sbin/agetty as 71
Feb 17 11:07:40 localhost systemd[1]: getty@tty2.service changed dead -> running
Feb 17 11:07:40 localhost systemd[1]: Job getty@tty2.service/start finished, result=done
Feb 17 11:07:40 localhost systemd[67]: Executing: /sbin/agetty tty1 38400
Feb 17 11:07:40 localhost systemd[1]: Started Getty on tty2.
Feb 17 11:07:40 localhost systemd[1]: Starting Getty on tty4...
Feb 17 11:07:40 localhost systemd[1]: About to execute: /sbin/agetty tty4 38400
Feb 17 11:07:40 localhost systemd[1]: Forked /sbin/agetty as 73
Feb 17 11:07:40 localhost systemd[1]: getty@tty4.service changed dead -> running
Feb 17 11:07:40 localhost systemd[1]: Job getty@tty4.service/start finished, result=done
Feb 17 11:07:40 localhost systemd[1]: Started Getty on tty4.
Feb 17 11:07:40 localhost systemd[1]: Starting Getty on tty3...
Feb 17 11:07:40 localhost systemd[1]: About to execute: /sbin/agetty tty3 38400
Feb 17 11:07:40 localhost systemd[1]: Forked /sbin/agetty as 74
Feb 17 11:07:40 localhost systemd[1]: getty@tty3.service changed dead -> running
Feb 17 11:07:40 localhost systemd[1]: Job getty@tty3.service/start finished, result=done
Feb 17 11:07:40 localhost systemd[1]: Started Getty on tty3.
Feb 17 11:07:40 localhost systemd[1]: Starting Login Prompts.
Feb 17 11:07:40 localhost systemd[1]: getty.target changed dead -> active
Feb 17 11:07:40 localhost systemd[1]: Job getty.target/start finished, result=done
Feb 17 11:07:40 localhost systemd[71]: Executing: /sbin/agetty tty2 38400
Feb 17 11:07:40 localhost systemd[74]: Executing: /sbin/agetty tty3 38400
Feb 17 11:07:40 localhost systemd[1]: Reached target Login Prompts.
Feb 17 11:07:40 localhost systemd[1]: Starting Multi-User.
Feb 17 11:07:40 localhost systemd[1]: multi-user.target changed dead -> active
Feb 17 11:07:40 localhost systemd[1]: Job multi-user.target/start finished, result=done
Feb 17 11:07:40 localhost kernel: input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input2
Feb 17 11:07:40 localhost kernel: ACPI: Power Button [PWRF]
Feb 17 11:07:40 localhost kernel: input: Sleep Button as /devices/LNXSYSTM:00/LNXSLPBN:00/input/input3
Feb 17 11:07:40 localhost kernel: ACPI: Sleep Button [SLPF]
Feb 17 11:07:40 localhost kernel: ACPI: AC Adapter [AC] (on-line)
Feb 17 11:07:40 localhost kernel: ACPI: Video Device [GFX0] (multi-head: yes  rom: no  post: no)
Feb 17 11:07:40 localhost kernel: input: Video Bus as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/LNXVIDEO:00/input/input4
Feb 17 11:07:40 localhost kernel: ACPI: Battery Slot [BAT0] (battery present)
Feb 17 11:07:40 localhost kernel: SCSI subsystem initialized
Feb 17 11:07:40 localhost kernel: e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
Feb 17 11:07:40 localhost kernel: e1000: Copyright (c) 1999-2006 Intel Corporation.
Feb 17 11:07:40 localhost kernel: ACPI: bus type USB registered
Feb 17 11:07:40 localhost kernel: usbcore: registered new interface driver usbfs
Feb 17 11:07:40 localhost kernel: usbcore: registered new interface driver hub
Feb 17 11:07:40 localhost kernel: input: PC Speaker as /devices/platform/pcspkr/input/input5
Feb 17 11:07:40 localhost kernel: libata version 3.00 loaded.
Feb 17 11:07:40 localhost systemd-journal[38]: Journal started
Feb 17 11:07:40 rear-deb8 sshd[41]: Server listening on 0.0.0.0 port 22.
Feb 17 11:07:40 rear-deb8 sshd[41]: Server listening on :: port 22.
Feb 17 11:07:41 rear-deb8 kernel: usbcore: registered new device driver usb
Feb 17 11:07:41 rear-deb8 kernel: ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
Feb 17 11:07:41 rear-deb8 kernel: ehci-pci: EHCI PCI platform driver
Feb 17 11:07:41 rear-deb8 kernel: ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
Feb 17 11:07:41 rear-deb8 kernel: psmouse serio1: alps: Unknown ALPS touchpad: E7=10 00 64, EC=10 00 64
Feb 17 11:07:41 rear-deb8 kernel: AVX version of gcm_enc/dec engaged.
Feb 17 11:07:41 rear-deb8 systemd[1]: Reached target Multi-User.
Feb 17 11:07:41 rear-deb8 systemd[1]: Got notification message for unit systemd-journald.service
Feb 17 11:07:41 rear-deb8 systemd[1]: systemd-journald.service: Got notification message from PID 38 (READY=1...)
Feb 17 11:07:41 rear-deb8 systemd[1]: systemd-journald.service: got STATUS=Processing requests...
Feb 17 11:07:41 rear-deb8 systemd[1]: Got notification message for unit systemd-journald.service
Feb 17 11:07:41 rear-deb8 systemd[1]: systemd-journald.service: Got notification message from PID 38 (READY=1...)
Feb 17 11:07:41 rear-deb8 systemd[1]: systemd-journald.service: got STATUS=Processing requests...
Feb 17 11:07:41 rear-deb8 systemd[1]: Received SIGCHLD from PID 51 (udevadm).
Feb 17 11:07:41 rear-deb8 systemd[1]: Child 37 (boot) died (code=exited, status=0/SUCCESS)
Feb 17 11:07:41 rear-deb8 systemd[1]: Child 37 belongs to rear-boot-helper.service
Feb 17 11:07:41 rear-deb8 systemd[1]: rear-boot-helper.service: main process exited, code=exited, status=0/SUCCESS
Feb 17 11:07:41 rear-deb8 systemd[1]: rear-boot-helper.service changed start -> dead
Feb 17 11:07:41 rear-deb8 systemd[1]: Job rear-boot-helper.service/start finished, result=done
Feb 17 11:07:41 rear-deb8 systemd[1]: Started Relax-and-Recover boot script.
Feb 17 11:07:41 rear-deb8 systemd[1]: rear-boot-helper.service: cgroup is empty
Feb 17 11:07:41 rear-deb8 systemd[1]: Child 51 (udevadm) died (code=exited, status=0/SUCCESS)
Feb 17 11:07:41 rear-deb8 systemd[1]: Child 51 belongs to systemd-udev-trigger.service
Feb 17 11:07:41 rear-deb8 systemd[1]: systemd-udev-trigger.service: main process exited, code=exited, status=0/SUCCESS
Feb 17 11:07:41 rear-deb8 systemd[1]: systemd-udev-trigger.service changed start -> exited
Feb 17 11:07:41 rear-deb8 systemd[1]: Job systemd-udev-trigger.service/start finished, result=done
Feb 17 11:07:41 rear-deb8 systemd[1]: Started udev Coldplug all Devices.
Feb 17 11:07:41 rear-deb8 systemd[1]: Startup finished in 1.138s (kernel) + 529ms (userspace) = 1.667s.
Feb 17 11:07:41 rear-deb8 systemd[1]: systemd-udev-trigger.service: cgroup is empty
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-ttyS0.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-devices-platform-serial8250-tty-ttyS0.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: Accepted new private connection.
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-ttyS1.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-devices-platform-serial8250-tty-ttyS1.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: Accepted new private connection.
Feb 17 11:07:41 rear-deb8 systemd[73]: Executing: /sbin/agetty tty4 38400
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-ttyS2.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-devices-platform-serial8250-tty-ttyS2.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-ttyS3.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-devices-platform-serial8250-tty-ttyS3.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: Got disconnect on private connection.
Feb 17 11:07:41 rear-deb8 systemd[1]: Got disconnect on private connection.
Feb 17 11:07:41 rear-deb8 kernel: alg: No test for __gcm-aes-aesni (__driver-gcm-aes-aesni)
Feb 17 11:07:41 rear-deb8 kernel: alg: No test for crc32 (crc32-pclmul)
Feb 17 11:07:41 rear-deb8 systemd[1]: Received SIGCHLD from PID 114 (net.agent).
Feb 17 11:07:41 rear-deb8 systemd[1]: Child 114 (net.agent) died (code=exited, status=0/SUCCESS)
Feb 17 11:07:41 rear-deb8 kernel: ppdev: user-space parallel port driver
Feb 17 11:07:41 rear-deb8 kernel: input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input6
Feb 17 11:07:41 rear-deb8 kernel: e1000 0000:00:03.0 eth0: (PCI:33MHz:32-bit) 08:00:27:90:7f:ea
Feb 17 11:07:41 rear-deb8 kernel: e1000 0000:00:03.0 eth0: Intel(R) PRO/1000 Network Connection
Feb 17 11:07:41 rear-deb8 kernel: piix4_smbus 0000:00:07.0: SMBus Host Controller at 0x4100, revision 0
Feb 17 11:07:41 rear-deb8 kernel: ahci 0000:00:0d.0: version 3.0
Feb 17 11:07:41 rear-deb8 kernel: ahci 0000:00:0d.0: SSS flag set, parallel bus scan disabled
Feb 17 11:07:41 rear-deb8 kernel: ahci 0000:00:0d.0: AHCI 0001.0100 32 slots 1 ports 3 Gbps 0x1 impl SATA mode
Feb 17 11:07:41 rear-deb8 kernel: ahci 0000:00:0d.0: flags: 64bit ncq stag only ccc 
Feb 17 11:07:41 rear-deb8 kernel: scsi0 : ahci
Feb 17 11:07:41 rear-deb8 kernel: ata1: SATA max UDMA/133 abar m8192@0xf0806000 port 0xf0806100 irq 21
Feb 17 11:07:41 rear-deb8 kernel: ata_piix 0000:00:01.1: version 2.13
Feb 17 11:07:41 rear-deb8 kernel: scsi1 : ata_piix
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-subsystem-net-devices-eth0.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-devices-pci0000:00-0000:00:03.0-net-eth0.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 kernel: scsi2 : ata_piix
Feb 17 11:07:41 rear-deb8 kernel: ata2: PATA max UDMA/33 cmd 0x1f0 ctl 0x3f6 bmdma 0xd000 irq 14
Feb 17 11:07:41 rear-deb8 kernel: ata3: PATA max UDMA/33 cmd 0x170 ctl 0x376 bmdma 0xd008 irq 15
Feb 17 11:07:41 rear-deb8 kernel: ehci-pci 0000:00:0b.0: EHCI Host Controller
Feb 17 11:07:41 rear-deb8 kernel: ehci-pci 0000:00:0b.0: new USB bus registered, assigned bus number 1
Feb 17 11:07:41 rear-deb8 kernel: ehci-pci 0000:00:0b.0: irq 19, io mem 0xf0805000
Feb 17 11:07:41 rear-deb8 systemd[1]: Received SIGCHLD from PID 122 (net.agent).
Feb 17 11:07:41 rear-deb8 systemd[1]: Child 122 (net.agent) died (code=exited, status=0/SUCCESS)
Feb 17 11:07:41 rear-deb8 kernel: ehci-pci 0000:00:0b.0: USB 2.0 started, EHCI 1.00
Feb 17 11:07:41 rear-deb8 kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Feb 17 11:07:41 rear-deb8 kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Feb 17 11:07:41 rear-deb8 kernel: usb usb1: Product: EHCI Host Controller
Feb 17 11:07:41 rear-deb8 kernel: usb usb1: Manufacturer: Linux 3.16.0-4-amd64 ehci_hcd
Feb 17 11:07:41 rear-deb8 kernel: usb usb1: SerialNumber: 0000:00:0b.0
Feb 17 11:07:41 rear-deb8 kernel: hub 1-0:1.0: USB hub found
Feb 17 11:07:41 rear-deb8 kernel: hub 1-0:1.0: 12 ports detected
Feb 17 11:07:41 rear-deb8 kernel: snd_intel8x0 0000:00:05.0: disable (unknown or VT-d) VM optimization
Feb 17 11:07:41 rear-deb8 kernel: ohci-pci: OHCI PCI platform driver
Feb 17 11:07:41 rear-deb8 kernel: ata3.00: ATAPI: VBOX CD-ROM, 1.0, max UDMA/133
Feb 17 11:07:41 rear-deb8 kernel: ata3.00: configured for UDMA/33
Feb 17 11:07:41 rear-deb8 kernel: tsc: Refined TSC clocksource calibration: 1696.961 MHz
Feb 17 11:07:41 rear-deb8 kernel: snd_intel8x0 0000:00:05.0: white list rate for 1028:0177 is 48000
Feb 17 11:07:41 rear-deb8 kernel: ohci-pci 0000:00:06.0: OHCI PCI host controller
Feb 17 11:07:41 rear-deb8 kernel: ohci-pci 0000:00:06.0: new USB bus registered, assigned bus number 2
Feb 17 11:07:41 rear-deb8 kernel: ohci-pci 0000:00:06.0: irq 22, io mem 0xf0804000
Feb 17 11:07:41 rear-deb8 systemd[1]: Failed to load configuration for sound.target: No such file or directory
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-devices-pci0000:00-0000:00:05.0-sound-card0.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: Trying to enqueue job sound.target/start/fail
Feb 17 11:07:41 rear-deb8 kernel: ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Feb 17 11:07:41 rear-deb8 kernel: ata1.00: ATA-6: VBOX HARDDISK, 1.0, max UDMA/133
Feb 17 11:07:41 rear-deb8 kernel: ata1.00: 16777216 sectors, multi 128: LBA48 NCQ (depth 31/32)
Feb 17 11:07:41 rear-deb8 kernel: ata1.00: configured for UDMA/133
Feb 17 11:07:41 rear-deb8 kernel: scsi 0:0:0:0: Direct-Access     ATA      VBOX HARDDISK    1.0  PQ: 0 ANSI: 5
Feb 17 11:07:41 rear-deb8 kernel: scsi 2:0:0:0: CD-ROM            VBOX     CD-ROM           1.0  PQ: 0 ANSI: 5
Feb 17 11:07:41 rear-deb8 kernel: sd 0:0:0:0: [sda] 16777216 512-byte logical blocks: (8.58 GB/8.00 GiB)
Feb 17 11:07:41 rear-deb8 kernel: sd 0:0:0:0: [sda] Write Protect is off
Feb 17 11:07:41 rear-deb8 kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Feb 17 11:07:41 rear-deb8 kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Feb 17 11:07:41 rear-deb8 kernel:  sda: sda1 sda2 < sda5 >
Feb 17 11:07:41 rear-deb8 kernel: sd 0:0:0:0: [sda] Attached SCSI disk
Feb 17 11:07:41 rear-deb8 kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0
Feb 17 11:07:41 rear-deb8 kernel: scsi 2:0:0:0: Attached scsi generic sg1 type 5
Feb 17 11:07:41 rear-deb8 kernel: usb usb2: New USB device found, idVendor=1d6b, idProduct=0001
Feb 17 11:07:41 rear-deb8 kernel: usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Feb 17 11:07:41 rear-deb8 kernel: usb usb2: Product: OHCI PCI host controller
Feb 17 11:07:41 rear-deb8 kernel: usb usb2: Manufacturer: Linux 3.16.0-4-amd64 ohci_hcd
Feb 17 11:07:41 rear-deb8 kernel: usb usb2: SerialNumber: 0000:00:06.0
Feb 17 11:07:41 rear-deb8 kernel: hub 2-0:1.0: USB hub found
Feb 17 11:07:41 rear-deb8 kernel: hub 2-0:1.0: 12 ports detected
Feb 17 11:07:41 rear-deb8 kernel: sr0: scsi3-mmc drive: 32x/32x xa/form2 tray
Feb 17 11:07:41 rear-deb8 kernel: cdrom: Uniform CD-ROM driver Revision: 3.20
Feb 17 11:07:41 rear-deb8 kernel: sr 2:0:0:0: Attached scsi CD-ROM sr0
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-disk-by\x2did-ata\x2dVBOX_HARDDISK_VBe56c88eb\x2d3055af2d.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-sda.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-devices-pci0000:00-0000:00:0d.0-ata1-host0-target0:0:0-0:0:0:0-block-sda.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-disk-by\x2did-ata\x2dVBOX_HARDDISK_VBe56c88eb\x2d3055af2d\x2dpart2.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-sda2.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-devices-pci0000:00-0000:00:0d.0-ata1-host0-target0:0:0-0:0:0:0-block-sda-sda2.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-disk-by\x2duuid-e696158e\x2d4494\x2d4c3a\x2d92ba\x2de216885eae97.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-disk-by\x2did-ata\x2dVBOX_HARDDISK_VBe56c88eb\x2d3055af2d\x2dpart5.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-sda5.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-devices-pci0000:00-0000:00:0d.0-ata1-host0-target0:0:0-0:0:0:0-block-sda-sda5.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-disk-by\x2duuid-0f2b56a2\x2d6257\x2d47b9\x2db568\x2ddab5d2ec9b05.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-disk-by\x2did-ata\x2dVBOX_HARDDISK_VBe56c88eb\x2d3055af2d\x2dpart1.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-sda1.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-devices-pci0000:00-0000:00:0d.0-ata1-host0-target0:0:0-0:0:0:0-block-sda-sda1.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-dvd.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-disk-by\x2did-ata\x2dVBOX_CD\x2dROM_VB2\x2d01700376.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-cdrom.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: dev-sr0.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 systemd[1]: sys-devices-pci0000:00-0000:00:01.1-ata3-host2-target2:0:0-2:0:0:0-block-sr0.device changed dead -> plugged
Feb 17 11:07:41 rear-deb8 kernel: usb 2-1: new full-speed USB device number 2 using ohci-pci
Feb 17 11:07:42 rear-deb8 kernel: usb 2-1: New USB device found, idVendor=80ee, idProduct=0021
Feb 17 11:07:42 rear-deb8 kernel: usb 2-1: New USB device strings: Mfr=1, Product=3, SerialNumber=0
Feb 17 11:07:42 rear-deb8 kernel: usb 2-1: Product: USB Tablet
Feb 17 11:07:42 rear-deb8 kernel: usb 2-1: Manufacturer: VirtualBox
Feb 17 11:07:42 rear-deb8 kernel: hidraw: raw HID events driver (C) Jiri Kosina
Feb 17 11:07:42 rear-deb8 kernel: usbcore: registered new interface driver usbhid
Feb 17 11:07:42 rear-deb8 kernel: usbhid: USB HID core driver
Feb 17 11:07:42 rear-deb8 kernel: input: VirtualBox USB Tablet as /devices/pci0000:00/0000:00:06.0/usb2/2-1/2-1:1.0/0003:80EE:0021.0001/input/input7
Feb 17 11:07:42 rear-deb8 kernel: hid-generic 0003:80EE:0021.0001: input,hidraw0: USB HID v1.10 Mouse [VirtualBox USB Tablet] on usb-0000:00:06.0-1/input0
Feb 17 11:07:43 rear-deb8 kernel: floppy0: no floppy controllers found
Feb 17 11:07:43 rear-deb8 kernel: work still pending

gdha commented at 2017-02-17 10:32:¶

@proura are you using VirtualBox in combination with vagrant? I've noticed the weirdest things may happen

proura commented at 2017-02-17 10:52:¶

@gdha no, not in this case.

proura commented at 2017-02-17 14:14:¶

I have found something new about what happens.

If the option StandardInput is set to "tty" and there are not specified the TTYPath it defaults to /dev/console. /dev/console and /dev/tty0 should be the same so if I do "echo hello > /dev/console" it will show "hello" into my actual console, as same as "echo hello > /dev/tty0"

But what happens if i try to do this in rescue mode in to my VirtualBox VM that has not serial ports activate?

RESCUE rear-deb8:~ # echo hello > /etc/console
-bash: echo: write error: Input/output error

Because of this error the sysinit.service does not start. Without serial ports in rescue mode the /dev/console is not the same as /dev/tty0. I have enabled one serial port on my VM VirtualBox Settings and all runs Ok!

Then I come to my KVM VM, that works perfectly, and I deleted the serial port that is enabled by default and I get the same error. ( @gdha can you try booting from PXE in a VM without serial ports, maybe you will reproduce the error )

So something wrong happens if a serial-less machine is trying to get into rescue mode.

gdha commented at 2017-02-17 15:51:¶

@proura in KVM I deleted the Serial Port (in my recover vm), and the recover worked fine. I interrupted the automatic boot and could still write to /dev/console, /dev/tty0 and /dev/tty1. Reboot was also ok.

jsmeix commented at 2017-02-17 15:54:¶

Only FYI in general regarding serial ports see the
probably related USE_SERIAL_CONSOLE setting
and the scripts which use that and do some
"automagic things", cf.
https://github.com/rear/rear/issues/937

Perhaps when there is no serial port one must explicitly
specify the right USE_SERIAL_CONSOLE value
(perhaps even together with KERNEL_CMDLINE)
to get things right?

didacog commented at 2017-02-18 20:10:¶

Hi @gdha @jsmeix,

@proura found the problem, I'd mistakenly hardcoded the kernel options in our PXE file when I pushed this part of code for DRLM 2.0 release.
I remember that I'd tested the serial console output with my Minnowboard (console=ttyS0,115200n8) to ensure that our new netboot also was working ok for serial console and, later, I merged the kernel options of my last tests to the code.
It just was working for us and we did not detect any issues with that, until we started to test automatic recovery.
Nothing is wrong with our GRUB2 configuration or the rescue sysinit service,
it was just my fault :-P

Well, I think that this issue can be closed and should never had been opened if I'd reviewed my code at time of preparing the DRLM 2.0 release.

I'm sorry for all of you for the waste of your time on this... :-(