[erledigt]mandriva-everytime.service bremst Booten aus

[man-draker]

Folgendes Phänomen:

Code: Alles auswählen

[man-draker@master ~]$ systemd-analyze blame
         29.813s mandriva-everytime.service
          6.439s network-up.service
          3.329s systemd-udev-settle.service
          1.080s shorewall6.service


Dazu:

Code: Alles auswählen

● mandriva-everytime.service - Reconfigure the system on administrator request
   Loaded: loaded (/usr/lib/systemd/system/mandriva-everytime.service; static; vendor preset: enabled)
   Active: active (exited) since Sa 2018-01-20 12:13:34 CET; 41s ago
  Process: 787 ExecStart=/etc/init.d/mandrake_everytime (code=exited, status=0/SUCCESS)
 Main PID: 787 (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/mandriva-everytime.service

Jan 20 12:13:07 master.jhwork service_harddrake[825]: moved file /boot/grub2/grub.cfg to /boot/grub2/grub.cfg.old
Jan 20 12:13:07 master.jhwork service_harddrake[825]: running: update-grub2
Jan 20 12:13:07 master.jhwork su[922]: (to root) root on none
Jan 20 12:13:32 master.jhwork su[922]: pam_systemd(su-l:session): Failed to create session: Die Wartezeit für die Verbindung ist abgelaufen
Jan 20 12:13:32 master.jhwork su[922]: pam_unix(su-l:session): session opened for user root by (uid=0)
Jan 20 12:13:34 master.jhwork su[922]: pam_unix(su-l:session): session closed for user root
Jan 20 12:13:34 master.jhwork service_harddrake[825]: update-grub2 logs: mesg: ttyname fehlgeschlagen: Unpassender IOCTL (I/O-Control) für das Gerät
                                                      GRUB-Konfigurationsdatei wird erstellt …
                                                      Thema gefunden: /boot/grub2/themes/maggy/theme.txt
                                                      Linux-Abbild gefunden: /boot/vmlinuz-4.14.13-desktop-1.mga6
                                                      initrd-Abbild gefunden: /boot/initrd-4.14.13-desktop-1.mga6.img
                                                      Linux-Abbild gefunden: /boot/vmlinuz-4.14.10-desktop-1.mga6
                                                      initrd-Abbild gefunden: /boot/initrd-4.14.10-desktop-1.mga6.img
                                                      Linux-Abbild gefunden: /boot/vmlinuz-desktop
                                                      initrd-Abbild gefunden: /boot/initrd-desktop.img
                                                      erledigt
Jan 20 12:13:34 master.jhwork service_harddrake[825]: created file /boot/.enough_space
Jan 20 12:13:34 master.jhwork service_harddrake[825]: removed files/directories /boot/.enough_space
Jan 20 12:13:34 master.jhwork systemd[1]: Started Reconfigure the system on administrator request.

Dachte ich, ich lege den Service mal still:

Code: Alles auswählen

systemctl disable mandriva-everytime.service

reichte aber nicht.

Erst ein

Code: Alles auswählen

systemctl mask mandriva-everytime.service

machte ihm den Gar aus.

Schon sieht die Sache wesentlich freundlicher aus:

Code: Alles auswählen

[man-draker@master ~]$ systemd-analyze blame
          6.457s network-up.service
          3.285s systemd-udev-settle.service
          1.089s shorewall6.service

Das Phänomen tritt - meiner Erinnerung nach - erst seit dem letzten Kernel-Update auf.

[doktor5000]

Code: Alles auswählen

echo HARDDRAKE_ONBOOT=no >> /etc/sysconfig/system

sollte eigentlich auch schon ausreichen.

Ursache können entweder zahlreiche binäre dkms-Module sein, oder die Wechselwirkung mit plymouth was zu Verzögerungen führt, siehe dazu https://bugs.mageia.org/show_bug.cgi?id=15230

[alf]

Ursache können entweder zahlreiche binäre dkms-Module sein

Werden die nicht durch dkms-autorebuild.service behandelt?

[man-draker]

Code: Alles auswählen

echo HARDDRAKE_ONBOOT=no >> /etc/sysconfig/system

sollte eigentlich auch schon ausreichen.

Tut es, ist aber nur ein Workaround.

Ursache können entweder zahlreiche binäre dkms-Module sein, oder die Wechselwirkung mit plymouth was zu Verzögerungen führt, siehe dazu https://bugs.mageia.org/show_bug.cgi?id=15230

DKMS kann es nicht sein, da kaum Module vorhanden sind.

Hier ist die Stelle, wo es klemmt:

Code: Alles auswählen

Jan 20 15:40:16 master.jhwork service_harddrake[832]: moved file /boot/grub2/grub.cfg to /boot/grub2/grub.cfg.old
Jan 20 15:40:16 master.jhwork service_harddrake[832]: running: update-grub2
Jan 20 15:40:16 master.jhwork su[929]: (to root) root on none
Jan 20 15:40:41 master.jhwork su[929]: pam_systemd(su-l:session): Failed to create session: Die Wartezeit für die Verbindung ist abgelaufen

Wenn das etwas mit plymouth zu tun hat, wäre der nächste Schritt, den wegzulassen.

[man-draker]

Wenn das etwas mit plymouth zu tun hat, wäre der nächste Schritt, den wegzulassen.

Der Boot-Parameter "noplymouth" bewirkt allerdings keine Besserung.

[man-draker]

Bei dem Service wird das Perl-Skript

Code: Alles auswählen

/usr/share/harddrake/service_harddrake

ausgeführt.

Wie bewege ich es dazu, genau zu protokollieren, was es tut und wie lange die jeweiligen Aktionen dauern?

[doktor5000]

Wie bewege ich es dazu, genau zu protokollieren, was es tut und wie lange die jeweiligen Aktionen dauern?

Das macht es bereits seit drakxtools-17.19-2.mga6 und das taucht auch im Journal auf, siehe u.a.

Code: Alles auswählen

journalctl -ab|grep service_harddrake
systemctl status mandriva-everytime.service -al -n50

Siehe auch https://bugs.mageia.org/show_bug.cgi?id=16684 oder https://bugs.mageia.org/show_bug.cgi?id=17299

[man-draker]

Die Kommandos ergeben dasselbe Bild: Es scheitert an einer "su-l: session".
Ich lasse mandriva.everytime jetzt weg und warte, dass sich die Zeiten bessern.

[unklar]

Du könntest es mit der debug-shell.service versuchen. Also

Code: Alles auswählen

systemctl enable debug-shell.service

das Teil einschalten, neu starten, auf tty9 wechseln und von dort mit journalctl arbeiten.

[man-draker]

OK, werde ich morgen mal testen.

Bringt keine neue Erkenntnis: Es bleibt bei der Fehlermeldung mit der Login-Session für root.

[unklar]

Blöde Frage...
macht es eigentlich einen Unterschied zwischen

Code: Alles auswählen

journalctl -ab|grep service_harddrake

und

Code: Alles auswählen

journalctl -ab | grep '/usr/share/harddrake/service_harddrake'

[man-draker]

Ja, ersteres führt zu einer Ausgabe, letzteres nicht.

[doktor5000]

Ja weil letzteres nach dem vollen Pfad greppt, das macht aber nicht viel Sinn weil alle die Ergebnisse bei der Suche nach dem Basis-Dateinamen auch mitkommen würden.
Es könnte allerdings sein dass noch andere Einträge des Dienstes mit harddrake oder mandriva-everytime geloggt werden ...

Code: Alles auswählen

journalctl -ab|grep -iE "harddrake|everytime"

sollte alles erschlagen. Ggf. mit grep -C5 oder so und noch die Zeilen ringsherum kurz betrachten oder einfach im Standard-Pager (less) einmal interaktiv suchen und hoch- / runterscrollen.

[man-draker]

Bitte, hier kommt der Output.
Die problematische Stelle kommt in den letzten Zeilen.

output.txt

(10.96 KiB) 105-mal heruntergeladen

[doktor5000]

Naja, fast 30s für update-grub2:

Jan 22 23:11:22 master.jhwork service_harddrake[845]: moved file /boot/grub2/grub.cfg to /boot/grub2/grub.cfg.old
Jan 22 23:11:22 master.jhwork service_harddrake[845]: running: update-grub2
Jan 22 23:11:49 master.jhwork service_harddrake[845]: update-grub2 logs: mesg: ttyname fehlgeschlagen: Unpassender IOCTL (I/O-Control) für das Gerät

Das kannst du ja auch händisch ausführen und schauen ob es solange dauert. Die Meldung danach kommt vermutlich daher dass zu der Zeit kein echtes Terminal verfügbar ist.

[man-draker]

Code: Alles auswählen

[root@master ~]# time update-grub2
GRUB-Konfigurationsdatei wird erstellt …
Thema gefunden: /boot/grub2/themes/maggy/theme.txt
Linux-Abbild gefunden: /boot/vmlinuz-4.14.13-desktop-1.mga6
initrd-Abbild gefunden: /boot/initrd-4.14.13-desktop-1.mga6.img
Linux-Abbild gefunden: /boot/vmlinuz-4.14.10-desktop-1.mga6
initrd-Abbild gefunden: /boot/initrd-4.14.10-desktop-1.mga6.img
Linux-Abbild gefunden: /boot/vmlinuz-desktop
initrd-Abbild gefunden: /boot/initrd-desktop.img
erledigt

real   0m0.800s
user   0m0.382s
sys   0m0.346s
[root@master ~]#

Ein ähnliches Problem mit einem fehlenden Terminal findet sich in einem älteren Thread in einem OpenMandriva-Forum und einem Thread in einem systemd-Forum. Beide sind aber schon Jahre alt. Was auffällt, ist, dass dort der Timeout für das Warten auf eine Terminalausgabe teils mit 30 Sekunden angegeben wird.

[doktor5000]

Stellt sich allerdings die Frage warum das nicht bei jedem auftritt ... irgendwelche Anpassungen in /root/.profile bzw. .bashrc oder ähnlichem, vielleicht auch unter /etc/profile.d oder so?


edit doktor5000: Hier sind noch ein paar Hinweise: https://superuser.com/questions/1160025 ... in-vagrant

Für Mageia hab ich nur was für die Phase wenn der Installer noch aktiv ist gefunden: https://bugs.mageia.org/show_bug.cgi?id=15857
Du könntest auch mal die os-prober Skripte durchkucken, das sind auch Shell-Skripte, evtl. weicht bei welchen davon der Shebang ab ?

[man-draker]

Schauen wir doch mal:

1. Auf dem Rechner mit dem Problem

.bashrc von root

Code: Alles auswählen

# .bashrc

PATH=/usr/local/sbin:/usr/sbin:/usr/local/bin:/usr/bin
ENV=$HOME/.bashrc
USERNAME="root"
export USERNAME ENV PATH

# Source global definitions
if [ -f /etc/bashrc ]; then
        . /etc/bashrc
fi

2. Das Pendant in einer VM, die keinen Stress macht:

Code: Alles auswählen

# .bashrc

PATH=/usr/local/sbin:/usr/sbin:/usr/local/bin:/usr/bin
ENV=$HOME/.bashrc
USERNAME="root"
export USERNAME ENV PATH

# Source global definitions
if [ -f /etc/bashrc ]; then
        . /etc/bashrc
fi

3. .bash_profile Rechner:

Code: Alles auswählen

# .bash_profile

# Get the aliases and functions
if [ -f ~/.bashrc ]; then
        . ~/.bashrc
fi

mesg n


4. dito VM:

Code: Alles auswählen

# .bash_profile

# Get the aliases and functions
if [ -f ~/.bashrc ]; then
        . ~/.bashrc
fi

mesg n


5. Inhalt von /etc/profile.d/ auf dem Rechner:

Code: Alles auswählen

[root@master ~]# ls /etc/profile.d/ -l
insgesamt 168
-rw-r--r-- 1 root root 1144 Jun  5  2017 01msec.csh
-rw-r--r-- 1 root root  518 Jun  5  2017 01msec.sh
-rw-r--r-- 1 root root  708 Mär 14  2017 10inputrc.csh
-rw-r--r-- 1 root root 3043 Mär 14  2017 10lang.csh
-rw-r--r-- 1 root root 5067 Mär 14  2017 10lang.sh
-rw-r--r-- 1 root root  209 Jul 10  2017 10mageia-release.csh
-rw-r--r-- 1 root root  117 Jul 10  2017 10mageia-release.sh
-rw-r--r-- 1 root root  583 Mär 14  2017 10tmpdir.csh
-rw-r--r-- 1 root root  559 Mär 14  2017 10tmpdir.sh
-rw-r--r-- 1 root root  440 Feb 12  2017 20bash-completion.sh
-rw-r--r-- 1 root root  235 Mär 30  2017 20less.csh
-rw-r--r-- 1 root root  301 Mär 30  2017 20less.sh
-rw-r--r-- 1 root root   49 Mär  6  2017 20mc.csh
-rw-r--r-- 1 root root  153 Mär  6  2017 20mc.sh
-rw-r--r-- 1 root root   63 Feb 26  2017 20screen.sh
-rw-r--r-- 1 root root  344 Mai 25  2017 30menustyle.csh
-rw-r--r-- 1 root root  226 Mai 25  2017 30menustyle.sh
-rw-r--r-- 1 root root  143 Dez 31 01:19 30python2.csh
-rw-r--r-- 1 root root  138 Dez 31 01:19 30python2.sh
-rw-r--r-- 1 root root  221 Mär  1  2017 40canberra.sh
-rwxr-xr-x 1 root root 1552 Jan  1  2016 40configure_keyboard.sh*
-rw-r--r-- 1 root root   41 Jan  1 19:59 40systemd.sh
-rw-r--r-- 1 root root  200 Mai 19  2017 50glib20.csh
-rw-r--r-- 1 root root  220 Mai 19  2017 50glib20.sh
-rw-r--r-- 1 root root   58 Jan 21  2011 50pilot.csh
-rw-r--r-- 1 root root   66 Jan 21  2011 50pilot.sh
-rw-r--r-- 1 root root 1852 Jan  3  2017 60alias.sh
-rwxr-xr-x 1 root root  245 Mär 16  2017 60qt4.sh*
-rwxr-xr-x 1 root root  128 Jul  1  2017 60qt5.csh*
-rwxr-xr-x 1 root root  227 Jul  1  2017 60qt5.sh*
-rw-r--r-- 1 root root  231 Feb 10  2016 90qtdir3.csh
-rw-r--r-- 1 root root  196 Feb 10  2016 90qtdir3.sh
-rw-r--r-- 1 root root  134 Dez 28 01:24 90ssh-client.sh
-rw-r--r-- 1 root root  560 Jan  3  2017 95bash-extras.sh
-rw-r--r-- 1 root root 1909 Aug 11  2016 99keychain.csh
-rw-r--r-- 1 root root 1579 Aug 11  2016 99keychain.sh
-rwxr-xr-x 1 root root   64 Dez  9  2016 gconf.csh*
-rwxr-xr-x 1 root root   75 Dez  9  2016 gconf.sh*
-rwxr-xr-x 1 root root  269 Feb 12  2016 numlock.sh*
-rw-r--r-- 1 root root 2315 Dez 10  2016 udisks-bash-completion.sh
-rw-r--r-- 1 root root 1941 Mai 10  2017 vte.sh

6. dito in der VM:

Code: Alles auswählen

[root@localhost ~]# ls -l /etc/profile.d/
insgesamt 160
-rw-r--r-- 1 root root 1144 Jun  5  2017 01msec.csh
-rw-r--r-- 1 root root  518 Jun  5  2017 01msec.sh
-rw-r--r-- 1 root root  708 Mär 14  2017 10inputrc.csh
-rw-r--r-- 1 root root 3043 Mär 14  2017 10lang.csh
-rw-r--r-- 1 root root 5067 Mär 14  2017 10lang.sh
-rw-r--r-- 1 root root  209 Jul 10  2017 10mageia-release.csh
-rw-r--r-- 1 root root  117 Jul 10  2017 10mageia-release.sh
-rw-r--r-- 1 root root  583 Mär 14  2017 10tmpdir.csh
-rw-r--r-- 1 root root  559 Mär 14  2017 10tmpdir.sh
-rw-r--r-- 1 root root  440 Feb 12  2017 20bash-completion.sh
-rw-r--r-- 1 root root  235 Mär 30  2017 20less.csh
-rw-r--r-- 1 root root  301 Mär 30  2017 20less.sh
-rw-r--r-- 1 root root   49 Mär  6  2017 20mc.csh
-rw-r--r-- 1 root root  153 Mär  6  2017 20mc.sh
-rw-r--r-- 1 root root   63 Feb 26  2017 20screen.sh
-rw-r--r-- 1 root root  344 Mai 25  2017 30menustyle.csh
-rw-r--r-- 1 root root  226 Mai 25  2017 30menustyle.sh
-rw-r--r-- 1 root root  143 Dez 31 01:19 30python2.csh
-rw-r--r-- 1 root root  138 Dez 31 01:19 30python2.sh
-rw-r--r-- 1 root root  221 Mär  1  2017 40canberra.sh
-rwxr-xr-x 1 root root 1552 Jan  1  2016 40configure_keyboard.sh*
-rw-r--r-- 1 root root   41 Jan  1 19:59 40systemd.sh
-rw-r--r-- 1 root root  200 Mai 19  2017 50glib20.csh
-rw-r--r-- 1 root root  220 Mai 19  2017 50glib20.sh
-rw-r--r-- 1 root root 1852 Jan  3  2017 60alias.sh
-rwxr-xr-x 1 root root  245 Mär 16  2017 60qt4.sh*
-rwxr-xr-x 1 root root  128 Jul  1  2017 60qt5.csh*
-rwxr-xr-x 1 root root  227 Jul  1  2017 60qt5.sh*
-rw-r--r-- 1 root root   52 Dez 28 01:24 90ssh-askpass.csh
-rw-r--r-- 1 root root   52 Dez 28 01:24 90ssh-askpass.sh
-rw-r--r-- 1 root root  134 Dez 28 01:24 90ssh-client.sh
-rw-r--r-- 1 root root  560 Jan  3  2017 95bash-extras.sh
-rwxr-xr-x 1 root root   64 Dez  9  2016 gconf.csh*
-rwxr-xr-x 1 root root   75 Dez  9  2016 gconf.sh*
-rw-r--r-- 1 root root  118 Feb  5  2016 ladspa.csh
-rw-r--r-- 1 root root  121 Feb  5  2016 ladspa.sh
-rwxr-xr-x 1 root root  269 Feb 12  2016 numlock.sh*
-rw-r--r-- 1 root root 2315 Dez 10  2016 udisks-bash-completion.sh
-rw-r--r-- 1 root root 1941 Mai 10  2017 vte.sh


Angabe zu /etc/profile beide identisch:

Code: Alles auswählen

[root@master ~]# ls -l /etc/profile
-rw-r--r-- 1 root root 859 Aug 31  2016 /etc/profile
[root@master ~]#

Code: Alles auswählen

[root@localhost ~]# less /etc/profile
[root@localhost ~]# ls -l /etc/profile                                                                                 
-rw-r--r-- 1 root root 859 Aug 31  2016 /etc/profile                                                                       
[root@localhost ~]#


[man-draker]

Also: Nachdem heute eine neue Systemd-Version kam, habe ich beim angeratenen Reboot den Service mitlaufen lassen.
Der Fehler ist noch da.

Inzwischen stelle ich mir die Frage, warum eigentlich der grub2_update jedes Mal losläuft?
Auf keinem meiner anderen Rechner (BIOS,UEFI oder VM) tut er das.
Evtl. ist es gar nicht geplant, dass zu diesem Zeitpunkt ein root-login Terminal existiert.

Bei anderen Benutzern tritt das Problem evtl. nur auf, wenn etwas an der Hardware geändert wurde, und dann werden einmalig 30 Sek. Verzögerung hingenommen.

Das einzig Besondere an dem Problemrechner gegenüber den anderen Rechnern, ist eine

Code: Alles auswählen

05:00.0 VGA compatible controller: Advanced Micro Devices, Inc. [AMD/ATI] Cape Verde XT [Radeon HD 7770/8760 / R7 250X]

die mit dem

Code: Alles auswählen

[    41.554] (II) RADEON: Driver for ATI/AMD Radeon chipsets:

läuft.

Der zugehörige Abschnitt der xorg.conf:

Code: Alles auswählen

Section "Device"
    Identifier "device1"
    VendorName "Advanced Micro Devices, Inc. [AMD/ATI]"
    BoardName "ATI Radeon HD 5000 to HD 6300 (radeon/fglrx)"
    Driver "ati"
    Option "DPMS"
    Option "AccelMethod" "EXA"
EndSection


Nur sehe ich da keinen Zusammenhang.

[man-draker]

Neue Hardware, neues Bootverhalten:

Code: Alles auswählen

[root@localhost ~]# systemd-analyze blame
          3.580s network-up.service
          2.213s mandriva-everytime.service
          1.663s shorewall6.service
           839ms shorewall.service
           662ms systemd-udev-settle.service
           549ms postfix.service
           169ms network.service
           152ms dev-sda5.device
           125ms cpupower.service
            89ms resolvconf.service
            78ms mga-bg-res.service
            75ms systemd-hostnamed.service
            75ms upower.service
            52ms partmon.service
            48ms fedora-storage-init.service
            44ms systemd-udevd.service
            42ms systemd-journal-flush.service
            38ms systemd-tmpfiles-clean.service
            37ms gssproxy.service
            32ms systemd-udev-trigger.service
            30ms accounts-daemon.service
            28ms systemd-journald.service
            28ms systemd-vconsole-setup.service
lines 1-23


Also Thema durch.

Ach ja: Keine Merkwürdigkeiten bei der Installation. Ist aber auch kein Notebook.