Bug 699114 - FIXED_IN_GIT: stopping mysql doesn't work
Summary: FIXED_IN_GIT: stopping mysql doesn't work
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: systemd
Version: 15
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Lennart Poettering
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 700173 700341 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-04-23 09:03 UTC by hannes
Modified: 2011-07-31 04:01 UTC (History)
18 users (show)

Fixed In Version: systemd-26-1.fc15
Clone Of:
Environment:
Last Closed: 2011-05-01 03:29:12 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
dmesg (86.19 KB, text/plain)
2011-04-23 09:03 UTC, hannes
no flags Details
systemd-analyze plot > boot.svg (281.55 KB, image/svg+xml)
2011-04-23 09:04 UTC, hannes
no flags Details
dmesg with systemd.log_level=debug and systemd.log_target=kmsg and after try shutdown (123.56 KB, text/plain)
2011-04-25 07:21 UTC, Alexei Panov
no flags Details
dmesg after 3 minutes wait (123.55 KB, text/plain)
2011-04-27 15:54 UTC, Alexei Panov
no flags Details
dmesg with default shutdown settings in kdm (123.51 KB, text/x-log)
2011-04-27 17:30 UTC, Alexei Panov
no flags Details

Description hannes 2011-04-23 09:03:19 UTC
Created attachment 494387 [details]
dmesg

Description of problem:
Since a few day I am not able to shut down my fedora 15 install properly. The X-Server is terminated and I just got a blinking cursor in the upper left. I am able to switch to different ttys but I could not login.
I use xfce and gdm to start my desktop environment. I tried other methods to shut down like 'halt' or 'init 0' but both did yield just the same result as any other method from gdm or from within xfce.

Version-Release number of selected component (if applicable):
rpm -qa | grep systemd
systemd-sysv-25-1.fc15.x86_64
systemd-gtk-25-1.fc15.x86_64
systemd-25-1.fc15.x86_64
systemd-units-25-1.fc15.x86_64

I am not sure if systemd is responsible for this at all.
How reproducible:
Always

Actual results:
Non-responsive machine which doesn't shut down

Expected results:
Clean shutdown!

Additional info:

Comment 1 hannes 2011-04-23 09:04:04 UTC
Created attachment 494388 [details]
systemd-analyze plot > boot.svg

Comment 2 hannes 2011-04-24 06:01:59 UTC
Just for the record a yum downgrade systemd* solved this issue for me. So it seems to be a regression in 25-1

Comment 3 Lennart Poettering 2011-04-24 12:15:53 UTC
Please boot with systemd.log_level=debug and systemd.log_target=kmsg on the kernel command line. Then symlink "/lib/systemd/system/rescue.target" to "/etc/systemd/system/kbrequest.target". Then reload, and shutdown.

If shutdown hangs, Press Alt-UpArrow. You should get a shell prompt. Please use "dmesg" to acquire the log output, save it somewhere, and attach here.

You should always be able to shut down the machine with clean file systems with "systemctl poweroff -f".

Comment 4 hannes 2011-04-24 13:23:06 UTC
As I said I could switch to different virtual consoles but I could not enter anything at the login prompt and therefore could not access a root-console and so I am not able to save dmesg.
Is there perhaps another way to save it?

Comment 5 Alexei Panov 2011-04-25 07:21:27 UTC
Created attachment 494621 [details]
dmesg with systemd.log_level=debug and systemd.log_target=kmsg and after try shutdown

I've boot system with systemd.log_level=debug and systemd.log_target=kmsg in kernel parameters.
Try shutdown (from KDE). System freeze.
I've connect on ssh and run dmesg > dmesg.log.

Comment 6 Alexei Panov 2011-04-25 07:22:06 UTC
This bug is affected to me too.

Comment 7 Alexei Panov 2011-04-25 07:30:00 UTC
And yes, systemctl poweroff -f works fine.

Comment 8 Morten Stevens 2011-04-25 10:42:04 UTC
I can confirm the problem. (after upgrade from 24-1 to 25-1)

Comment 9 Michał Piotrowski 2011-04-26 16:33:50 UTC
(In reply to comment #3)
> If shutdown hangs, Press Alt-UpArrow. You should get a shell prompt.

This trick doesn't work here - I can't get a shell. When I press alt + up arrow I only see a black screen. When I switch to second tty and then back I can see some messages about stopping mysql.

Best regards,
Michal

Comment 10 Lennart Poettering 2011-04-27 00:42:01 UTC
Alexei, your output shows nothing wrong. Can you make sure to wait for 3min when this hangs, because that's the timeout systemd has for everything.

Can somebody please do what I asked for in comment #3.

Michal, have you linked /etc/systemd/system/kbrequest.target as suggested in comment #3? Only then Alt-UpArrow will spawn a shell.

Comment 11 Michał Piotrowski 2011-04-27 05:14:07 UTC
(In reply to comment #10)
> Michal, have you linked /etc/systemd/system/kbrequest.target as suggested in
> comment #3? Only then Alt-UpArrow will spawn a shell.

Yes

$ ls -la
[..]
lrwxrwxrwx  1 root root   33 04-26 18:20 kbrequest.target -> /lib/systemd/system/rescue.target

but I never waited 3 minutes to see shell - so maybe it is about timeout. Will try again later.

Comment 12 Lennart Poettering 2011-04-27 15:13:26 UTC
(In reply to comment #11)
> (In reply to comment #10)
> > Michal, have you linked /etc/systemd/system/kbrequest.target as suggested in
> > comment #3? Only then Alt-UpArrow will spawn a shell.
> 
> Yes
> 
> $ ls -la
> [..]
> lrwxrwxrwx  1 root root   33 04-26 18:20 kbrequest.target ->
> /lib/systemd/system/rescue.target

Did you reload systemd with "systemctl daemon-reload"?

Anybody else can get me some useful output from the shutdown?

Comment 13 Michał Piotrowski 2011-04-27 15:30:37 UTC
(In reply to comment #12)
> Did you reload systemd with "systemctl daemon-reload"?

No, I had to add systemd.log_level=* to grub config and I rebooted system - should be enough I guess :)

Maybe I need to enable something in /etc/systemd/system.conf ? CrashShell?

Comment 14 rvcsaba 2011-04-27 15:50:27 UTC
Lennart,

I wrote a small shell script, but can't running from cron, because systemd halted crond.service... (Sorry my very poor english.)

#!/bin/bash

outfile='/root/systemd.debug.txt'
{
    separator='----------------------------------'
    cmd='rpm -q kernel selinux-policy systemd'
    echo "$cmd"
    $cmd
    echo "$separator"
    grubconf='/boot/grub/grub.conf'
    echo "$grubconf"
    echo
    cat "$grubconf"
    echo "$separator"
    cmd='dmesg'
    echo "$cmd"
    $cmd
} >"$outfile"
sync
systemctl poweroff -f
exit 0

How I running it? (If I use Alt-UpArrow, home position flashing cursor is off, my monitor is totally black.)

Comment 15 Alexei Panov 2011-04-27 15:54:19 UTC
Created attachment 495281 [details]
dmesg after 3 minutes wait

This dmesg after 3 minutes waiting.
Alt-UpArrow or Alt-DownArrow don't work. But I've switched on second console (Alt-Ctrl-F2), login (after symlink from comment #3) and get dmesg there.

Comment 16 Michał Piotrowski 2011-04-27 16:08:28 UTC
(In reply to comment #15)
> Alt-UpArrow or Alt-DownArrow don't work. But I've switched on second console
> (Alt-Ctrl-F2), login (after symlink from comment #3) and get dmesg there.

I wonder why I can not use this console - in my case TTY2 doesn't accept any chars.

Comment 17 rvcsaba 2011-04-27 16:14:04 UTC
(In reply to comment #16)

> in my case TTY2 doesn't accept any chars.

Same problem here.

Comment 18 Michal Schmidt 2011-04-27 16:46:19 UTC
(In reply to comment #15)
> This dmesg after 3 minutes waiting.

This one is useless. systemd did not even begin to shutdown, because you broke your kdm configuration:
[  135.777880] kdm[4001]: Failed to execute shutdown command "systemctl poweroff -f"
Please test with the original kdmrc setting HaltCmd=/sbin/poweroff

Comment 19 Michal Schmidt 2011-04-27 17:26:14 UTC
Hooray, I can reproduce this!
1) systemctl start mysqld.service
2) init 6

No timeout kicks in. I can still login via ssh and see:

# systemctl list-jobs | grep running
1118 mysqld.service            stop            running

# systemctl status mysqld.service
mysqld.service - SYSV: MySQL database server.
          Loaded: loaded (/etc/rc.d/init.d/mysqld)
          Active: deactivating (stop-sigterm) since Wed, 27 Apr 2011 19:18:44 +0200; 3min 24s ago
         Process: 2056 ExecStop=/etc/rc.d/init.d/mysqld stop (code=exited, status=0/SUCCESS)
         Process: 1708 ExecStart=/etc/rc.d/init.d/mysqld start (code=exited, status=0/SUCCESS)
        Main PID: 1943
          CGroup: name=systemd:/system/mysqld.service

dmesg has this to say about mysql:
[   48.374889] systemd[1]: Trying to enqueue job mysqld.service/start/replace
[   48.375172] systemd[1]: Installed new job mysqld.service/start as 937
[   48.375180] systemd[1]: Enqueued job mysqld.service/start as 937
[   48.375665] systemd[1]: About to execute: /etc/rc.d/init.d/mysqld start
[   48.397532] systemd[1]: Forked /etc/rc.d/init.d/mysqld as 1708
[   48.397574] systemd[1]: mysqld.service changed dead -> start
[   48.397926] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.Get() on /org/freedesktop/systemd1/unit/mysqld_2eservice
[   50.797472] systemd[1]: Received SIGCHLD from PID 1708 (mysqld).
[   50.811571] systemd[1]: Got SIGCHLD for process 1708 (mysqld)
[   50.811649] systemd[1]: Child 1708 belongs to mysqld.service
[   50.811657] systemd[1]: mysqld.service: control process exited, code=exited status=0
[   50.811661] systemd[1]: mysqld.service got final SIGCHLD for state start
[   50.812925] systemd[1]: mysqld.service: Supervising process 1943 which is not our child. We'll most likely not notice when it exits.
[   50.813277] systemd[1]: mysqld.service changed start -> running
[   50.813288] systemd[1]: Job mysqld.service/start finished, result=done
[  117.953131] systemd[1]: Failed to load configuration for mysql.service: No such file or directory
[  117.953342] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/mysql_2eservice
[  120.557064] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/mysqld_2eservice
[  127.551008] systemd[1]: Installed new job mysqld.service/stop as 1118
[  130.387791] systemd[1]: About to execute: /etc/rc.d/init.d/mysqld stop
[  130.419169] systemd[1]: Forked /etc/rc.d/init.d/mysqld as 2056
[  130.419237] systemd[1]: mysqld.service changed running -> stop
[  131.367790] systemd[1]: Received SIGCHLD from PID 1747 (mysqld_safe).
[  131.368782] systemd[1]: Got SIGCHLD for process 1747 (mysqld_safe)
[  131.466527] systemd[1]: Received SIGCHLD from PID 2056 (mysqld).
[  131.466573] systemd[1]: Got SIGCHLD for process 2056 (mysqld)
[  131.466647] systemd[1]: Child 2056 belongs to mysqld.service
[  131.466658] systemd[1]: mysqld.service: control process exited, code=exited status=0
[  131.466666] systemd[1]: mysqld.service got final SIGCHLD for state stop
[  131.466687] systemd[1]: mysqld.service changed stop -> stop-sigterm
[  131.471123] systemd[1]: mysqld.service: cgroup is empty

I wonder what this really means:
Supervising process 1943 which is not our child. We'll most likely not notice when it exits.

Comment 20 Alexei Panov 2011-04-27 17:30:25 UTC
Created attachment 495291 [details]
dmesg with default shutdown settings in kdm

Yes, I'm sorry. I've changed this options and attach new dmesg.
I've get dmesg only over ssh.

Comment 21 Michal Schmidt 2011-04-27 17:32:53 UTC
Instead of shutting down, to reproduce the problem it is sufficient to try to stop the running mysqld.service. It will go into the stop-sigterm state and stay there forever, with no processes in the cgroup.

Comment 22 hannes 2011-04-27 17:35:53 UTC
I can confirm this, too.

Comment 23 Michal Schmidt 2011-04-27 17:45:14 UTC
*** Bug 700173 has been marked as a duplicate of this bug. ***

Comment 24 Lennart Poettering 2011-04-27 20:05:59 UTC
Regarding: "Supervising process 1943 which is not our child. We'll most likely not notice when it exits." So, MySQL puts a PID in the PID file that is not a child of init. That means if it dies systemd will not get a SIGCHLD for it and thus not detect that it is gone. Normally that shouldn't hurt much though, because we also get a notification when the cgroup becomes empty. That means we won't be be able to collect exit status and stuff, but we will still notice when mysql is gone.

That's the theory at least, alas it doesn't seem to work.

Michal, thanks for tracking this down, I'll try to reproduce this here, too.

Comment 25 Lennart Poettering 2011-04-28 02:57:31 UTC
Fixed in git.

Comment 26 hannes 2011-04-28 07:02:09 UTC
Thanks a lot for this fix and for the debugging, Michal and Lennart. 
Is there an easy way to incorporate this patch into the package? Are you perhaps going to release a new version soon?

Is it better to patch the 25-1 package or even use the git-master for a new package.

Comment 27 Alexei Panov 2011-04-28 09:07:54 UTC
Lennart, Michal thanks for fix.

Comment 28 Michal Schmidt 2011-04-28 19:01:15 UTC
*** Bug 700341 has been marked as a duplicate of this bug. ***

Comment 29 Michał Piotrowski 2011-04-28 22:50:38 UTC
Great that you manage to track down the root of the problem. I hope that systemd v26 will be available soon.

[192548.839883] systemd[1]: Reloading.
[192549.222885] systemd[1]: mysqld.service: Supervising process 999 which is not our child. We'll most likely not notice when it exits.

:)

(In reply to comment #13)
> (In reply to comment #12)
> > Did you reload systemd with "systemctl daemon-reload"?
> 
> No, I had to add systemd.log_level=* to grub config and I rebooted system -
> should be enough I guess :)
> 
> Maybe I need to enable something in /etc/systemd/system.conf ? CrashShell?

Any tips for the future how to run this shell?

Comment 30 Fedora Update System 2011-04-30 02:57:39 UTC
systemd-26-1.fc15 has been submitted as an update for Fedora 15.
https://admin.fedoraproject.org/updates/systemd-26-1.fc15

Comment 31 Alexei Panov 2011-04-30 08:16:42 UTC
This bug is fixed in new packages. Really many thanks.
P.S. I've added karma in bodhi.

Comment 32 Michał Piotrowski 2011-04-30 10:12:07 UTC
Thanks!

Best regards,
Michal

Comment 33 Fedora Update System 2011-05-01 03:28:47 UTC
systemd-26-1.fc15 has been pushed to the Fedora 15 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 34 shane 2011-06-20 21:52:10 UTC
i can start and stop mysqld from the init script but i am getting lots of these error messages.

Jun 20 16:24:00 host01 systemd[1]: mysqld.service: Supervising process 1357 which is not our child. We'll most likely not notice when it exits.
Jun 20 16:26:33 host01 systemd[1]: mysqld.service: Supervising process 1954 which is not our child. We'll most likely not notice when it exits.
Jun 20 16:31:05 host01 systemd[1]: mysqld.service: Supervising process 2285 which is not our child. We'll most likely not notice when it exits.


$ ps axu | egrep 1357\|1954\|2285
mysql     2285  0.1  2.0 486140 41416 ?        Sl   16:31   0:01 /usr/libexec/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock

501       2356  0.0  0.0 106308   784 pts/0    S+   16:51   0:00 egrep --color=auto 1357|1954|2285


Note You need to log in before you can comment on or make changes to this bug.