Bug #7188
Admin socket files are lost on log rotation calling initctl reload (ubuntu 13.04 only)
100%
Description
Workaround¶
Using restart instead of reload restarts the daemons instead of sending them a signal that gracefully reopens the log.
perl -pi -e 's/reload/restart/' /etc/logrotate.d/ceph
Description¶
Steps to reproduce, using a fresh install of Ubuntu raring (it does not show on Ubuntu trusty) and firefly. The /etc/ceph/ceph-mon.conf is as follows:
description "Ceph MON" start on ceph-mon stop on runlevel [!2345] or stopping ceph-mon-all respawn respawn limit 5 30 limit nofile 16384 16384 pre-start script set -e test -x /usr/bin/ceph-mon || { stop; exit 0; } test -d "/var/lib/ceph/mon/${cluster:-ceph}-$id" || { stop; exit 0; } install -d -m0755 /var/run/ceph end script instance ${cluster:-ceph}/$id export cluster export id # this breaks oneiric #usage "cluster = name of cluster (defaults to 'ceph'); id = monitor instance id" exec /usr/bin/ceph-mon --cluster="${cluster:-ceph}" -i "$id" -f post-stop script # Cleanup socket in case of segfault rm -f "/var/run/ceph/ceph-mon.$id.asok" end script
The line of interest is exec /usr/bin/ceph-mon --cluster="${cluster:-ceph}" -i "$id" -f which is apparently sometime exec'ed and sometime run thru a shell without exec.
root@raring:/etc/ceph# start ceph-mon id=raring ceph-mon (ceph/raring) start/running, process 6488 root@raring:/etc/ceph# ps fauwwx | grep ceph- root 6488 0.0 0.0 4444 624 ? Ss 16:17 0:00 /bin/sh -e -c /usr/bin/ceph-mon --cluster="${cluster:-ceph}" -i "$id" -f /bin/sh root 6489 1.0 0.8 134772 9116 ? Sl 16:17 0:00 \_ /usr/bin/ceph-mon --cluster=ceph -i raring -f root@raring:/etc/ceph# reload ceph-mon id=raring root@raring:/etc/ceph# ls -l /var/run/ceph total 0 root@raring:/etc/ceph# status ceph-mon id=raring status: Unknown instance: ceph/raring root@raring:/etc/ceph# ps fauwwx | grep ceph- root 6489 0.0 1.0 135796 10416 ? Sl 16:17 0:00 /usr/bin/ceph-mon --cluster=ceph -i raring -f
Note that if the "/bin/sh" is not present, the problem does not show. Run restart until the "/bin/sh" process parent of /usr/bin/ceph-mon shows up.
reload kills the intermediate shell, notices that it is dead and run the post-stop script that removes the asok file. The ceph-mon is no longer managed by upstart and cannot be notified.
Initial report¶
My /var/run/ceph/*.asok for OSDs and mon were mysteriously gone when I came back in the morning after running overnight. I noticed that they had disappeared at the same time as a log rotation, and sure enough calling "logrotate --force /etc/logrotate.d/ceph" leaves services running with no socket files.
It looks like the part that's causing the problem is the "initctl reload ceph-mon id=xxx", which on my system is leaving the original service PID running, and trying to start a new one at the same time: logs show the new process failing to start with "failed to create new leveldb store" while the existing process continues to function. Presumably it's the new process which is deleting the socket files in spite of failing to come up successfully.
Package in use is 0.72.2-1raring.
This is kind of severe for anyone using a monitoring system that relies on the socket files to see and talk to the Ceph processes. If we can show that this issue is limited to ubuntu 13.04 then this is less of a big deal: I wouldn't be surprised if it's quite sensitive to extra distro version in use.
Related issues
Associated revisions
common: ping existing admin socket before unlink
When a daemon initializes it tries to create an admin socket and unlinks
any pre-existing file, regardless. If such a file is in use, it causes
the existing daemon to loose its admin socket.
The AdminSocketClient::ping is implemented to probe an existing socket,
using the "0" message. The AdminSocket::bind_and_listen function is
modified to call ping() on when it finds existing file. It unlinks the
file only if the ping fails.
http://tracker.ceph.com/issues/7188 fixes: #7188
Backport: emperor, dumpling
Reviewed-by: Sage Weil <sage@inktank.com>
Signed-off-by: Loic Dachary <loic@dachary.org>
common: ping existing admin socket before unlink
When a daemon initializes it tries to create an admin socket and unlinks
any pre-existing file, regardless. If such a file is in use, it causes
the existing daemon to loose its admin socket.
The AdminSocketClient::ping is implemented to probe an existing socket,
using the "0" message. The AdminSocket::bind_and_listen function is
modified to call ping() on when it finds existing file. It unlinks the
file only if the ping fails.
http://tracker.ceph.com/issues/7188 fixes: #7188
Backport: emperor, dumpling
Reviewed-by: Sage Weil <sage@inktank.com>
Signed-off-by: Loic Dachary <loic@dachary.org>
(cherry picked from commit 45600789f1ca399dddc5870254e5db883fb29b38)
common: ping existing admin socket before unlink
When a daemon initializes it tries to create an admin socket and unlinks
any pre-existing file, regardless. If such a file is in use, it causes
the existing daemon to loose its admin socket.
The AdminSocketClient::ping is implemented to probe an existing socket,
using the "0" message. The AdminSocket::bind_and_listen function is
modified to call ping() on when it finds existing file. It unlinks the
file only if the ping fails.
http://tracker.ceph.com/issues/7188 fixes: #7188
Backport: emperor, dumpling
Reviewed-by: Sage Weil <sage@inktank.com>
Signed-off-by: Loic Dachary <loic@dachary.org>
(cherry picked from commit 45600789f1ca399dddc5870254e5db883fb29b38)
History
#1 Updated by Sage Weil about 10 years ago
- Priority changed from Normal to Urgent
- Source changed from other to Development
#2 Updated by Loïc Dachary about 10 years ago
- Assignee set to Loïc Dachary
Not sure if I can fix it but I'll give it a shot.
#3 Updated by Loïc Dachary about 10 years ago
ceph-osd installs a sighup handler which reopens logs . It is triggered by logrotate.conf via initctl reload which sends a SIGHUP to ceph-osd which reopens the logs
#4 Updated by Loïc Dachary about 10 years ago
From a fresh install of ubuntu 13.04 the packages are installed with
wget -q -O- 'https://ceph.com/git/?p=ceph.git;a=blob_plain;f=keys/release.asc' | sudo apt-key add - echo deb http://ceph.com/debian-emperor/ $(lsb_release -sc) main | sudo tee /etc/apt/sources.list.d/ceph.list sudo apt-get update sudo apt-get --yes install ceph ceph-common
A /etc/ceph/ceph.conf file is created
# cat /etc/ceph/ceph.conf [global] fsid = beb3b8f3-1610-499b-b3c8-34f7a6610bf8 osd crush chooseleaf type = 0 mon host = 127.0.0.1 auth cluster required = none auth service required = none auth client required = none
A mon is run with
mkdir /var/lib/ceph/mon/ceph-0 ceph-mon --id 0 --mkfs --keyring /dev/null start ceph-mon id=0
The 10GB disk attached to the machine is used for an OSD with
# ceph-disk prepare /dev/sdb INFO:ceph-disk:Will colocate journal with data on /dev/sdb Creating new GPT entries. Information: Moved requested sector from 34 to 2048 in order to align on 2048-sector boundaries. The operation has completed successfully. Information: Moved requested sector from 10485761 to 10487808 in order to align on 2048-sector boundaries. The operation has completed successfully. meta-data=/dev/sdb1 isize=2048 agcount=4, agsize=327615 blks = sectsz=512 attr=2, projid32bit=0 data = bsize=4096 blocks=1310459, imaxpct=25 = sunit=0 swidth=0 blks naming =version 2 bsize=4096 ascii-ci=0 log =internal log bsize=4096 blocks=2560, version=2 = sectsz=512 sunit=0 blks, lazy-count=1 realtime =none extsz=4096 blocks=0, rtextents=0 The operation has completed successfully.
and the admin socket responds
# ceph --admin-daemon /var/run/ceph/ceph-osd.0.asok version {"version":"0.72.2"}
and when reloading only the logs are re-open, the socket itself is left untouched
root@Host-002:~# ls -li /var/run/ceph/ceph-osd.0.asok 12464 srwxr-xr-x 1 root root 0 Feb 14 23:59 /var/run/ceph/ceph-osd.0.asok root@Host-002:~# ls -li /var/log/ceph/ceph-osd.0.log 276347 -rw-r--r-- 1 root root 0 Feb 15 00:20 /var/log/ceph/ceph-osd.0.log root@Host-002:~# mv /var/log/ceph/ceph-osd.0.log /tmp root@Host-002:~# reload ceph-osd cluster=ceph id=0 root@Host-002:~# ls -li /var/log/ceph/ceph-osd.0.log 276371 -rw-r--r-- 1 root root 0 Feb 15 00:21 /var/log/ceph/ceph-osd.0.log root@Host-002:~# ls -li /var/run/ceph/ceph-osd.0.asok 12464 srwxr-xr-x 1 root root 0 Feb 14 23:59 /var/run/ceph/ceph-osd.0.asok
the same thing happens when using logrotate:
root@Host-002:~# logrotate --force /etc/logrotate.d/ceph root@Host-002:~# ls -li /var/run/ceph/ceph-osd.0.asok 12464 srwxr-xr-x 1 root root 0 Feb 14 23:59 /var/run/ceph/ceph-osd.0.asok root@Host-002:~# ls -li /var/log/ceph/ceph-osd.0.log 276414 -rw-r--r-- 1 root root 0 Feb 15 00:23 /var/log/ceph/ceph-osd.0.log
#5 Updated by Loïc Dachary about 10 years ago
- Status changed from New to In Progress
- Target version set to v0.77
- % Done changed from 0 to 30
- Backport set to emperor, dumpling
Steps to reproduce:
root@Host-002:~# status ceph-osd id=0 ceph-osd (ceph/0) start/running, process 2772 root@Host-002:~# ls -l /var/run/ceph total 0 srwxr-xr-x 1 root root 0 Feb 15 00:42 ceph-mon.0.asok srwxr-xr-x 1 root root 0 Feb 15 00:41 ceph-osd.0.asok root@Host-002:~# ceph-osd --cluster=ceph -i 0 -f starting osd.0 at :/0 osd_data /var/lib/ceph/osd/ceph-0 /var/lib/ceph/osd/ceph-0/journal 2014-02-15 00:43:32.231893 7f40c2a327c0 -1 filestore(/var/lib/ceph/osd/ceph-0) FileStore::mount: lock_fsid failed 2014-02-15 00:43:32.232578 7f40c2a327c0 -1 ** ERROR: error converting store /var/lib/ceph/osd/ceph-0: (16) Device or resource busy root@Host-002:~# ls -l /var/run/ceph total 0 srwxr-xr-x 1 root root 0 Feb 15 00:42 ceph-mon.0.asok root@Host-002:~# status ceph-osd id=0 ceph-osd (ceph/0) start/running, process 2772 root@Host-002:~#
#6 Updated by Loïc Dachary about 10 years ago
- Status changed from In Progress to Fix Under Review
#7 Updated by Loïc Dachary about 10 years ago
- % Done changed from 30 to 80
#9 Updated by Loïc Dachary about 10 years ago
#10 Updated by Sage Weil about 10 years ago
- Status changed from Fix Under Review to Pending Backport
merged into next. want to wait a bit before backporting.
#11 Updated by Sage Weil about 10 years ago
- Severity changed from 3 - minor to 2 - major
#12 Updated by Loïc Dachary about 10 years ago
- Status changed from Pending Backport to Fix Under Review
#13 Updated by Loïc Dachary about 10 years ago
- % Done changed from 90 to 100
#14 Updated by Sage Weil about 10 years ago
- Status changed from Fix Under Review to Resolved
#15 Updated by Greg Farnum almost 10 years ago
- Status changed from Resolved to 12
- Target version deleted (
v0.77)
I think this fix was incomplete: https://www.mail-archive.com/ceph-users@lists.ceph.com/msg09754.html
We probably need to block on startup in the daemons, if they couldn't create their admin socket. Or start creating "/var/run/ceph/ceph-mon.a.2.asok" or something.
#16 Updated by Loïc Dachary almost 10 years ago
On a ceph 0.80.1 on a freshly installed ubuntu raring, when running
sudo stop ceph-all; sudo start ceph-all ; sudo logrotate --force /etc/logrotate.d/ceph
and the ceph-mon attempts to restart 5 times ( the respawn limit of the ceph-mon upstart script)
2014-05-23 13:35:31.224332 7f67eb6477c0 0 ceph version 0.80.1 (a38fe1169b6d2ac98b427334c12d7cf81f809b74), process ceph-mon, pid 24541 2014-05-23 13:35:31.228004 7f67eb6477c0 -1 failed to create new leveldb store 2014-05-23 13:35:31.248810 7f10460ac7c0 0 ceph version 0.80.1 (a38fe1169b6d2ac98b427334c12d7cf81f809b74), process ceph-mon, pid 24552 2014-05-23 13:35:31.252184 7f10460ac7c0 -1 failed to create new leveldb store 2014-05-23 13:35:31.275104 7f0bbcee37c0 0 ceph version 0.80.1 (a38fe1169b6d2ac98b427334c12d7cf81f809b74), process ceph-mon, pid 24563 2014-05-23 13:35:31.278270 7f0bbcee37c0 -1 failed to create new leveldb store 2014-05-23 13:35:31.302257 7fa1d9dbe7c0 0 ceph version 0.80.1 (a38fe1169b6d2ac98b427334c12d7cf81f809b74), process ceph-mon, pid 24575 2014-05-23 13:35:31.305587 7fa1d9dbe7c0 -1 failed to create new leveldb store 2014-05-23 13:35:31.326657 7fabd0cc47c0 0 ceph version 0.80.1 (a38fe1169b6d2ac98b427334c12d7cf81f809b74), process ceph-mon, pid 24588 2014-05-23 13:35:31.329453 7fabd0cc47c0 -1 failed to create new leveldb store
The asok file is removed.
#17 Updated by Loïc Dachary almost 10 years ago
The problem is confirmed to not happen on ubuntu trusty
#18 Updated by Loïc Dachary almost 10 years ago
- Description updated (diff)
#19 Updated by Loïc Dachary almost 10 years ago
- Description updated (diff)
#20 Updated by Loïc Dachary almost 10 years ago
- % Done changed from 100 to 80
#21 Updated by Loïc Dachary almost 10 years ago
- Description updated (diff)
#22 Updated by Loïc Dachary almost 10 years ago
Mail sent asking for advice on the best workaround to James Page and James Hunt cc'd ceph-devel.
#23 Updated by Loïc Dachary almost 10 years ago
- Description updated (diff)
#24 Updated by Loïc Dachary almost 10 years ago
- Description updated (diff)
#25 Updated by Loïc Dachary almost 10 years ago
- Description updated (diff)
#26 Updated by Hunter Nield almost 10 years ago
We had the same issue a few months back (http://tracker.ceph.com/issues/6043). We cheated and updated ceph's logrotate to use restart instead of reload
#27 Updated by Loïc Dachary almost 10 years ago
- Description updated (diff)
- Status changed from 12 to Won't Fix
- % Done changed from 80 to 100
Document the proposed workaround in the description for reference.
#28 Updated by Loïc Dachary almost 10 years ago
- Description updated (diff)
#29 Updated by Loïc Dachary almost 10 years ago
- Subject changed from Admin socket files are lost on log rotation calling initctl reload to Admin socket files are lost on log rotation calling initctl reload (ubuntu 13.04 only)