Project

General

Profile

Bug #7188

Admin socket files are lost on log rotation calling initctl reload (ubuntu 13.04 only)

Added by John Spray about 10 years ago. Updated almost 10 years ago.

Status:
Won't Fix
Priority:
Urgent
Assignee:
Category:
-
Target version:
-
% Done:

100%

Source:
Development
Tags:
Backport:
emperor, dumpling
Regression:
No
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

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

Duplicated by Ceph - Bug #6043: upstart does not reflect running ceph-osd daemons (ubuntu 13.04 only) Won't Fix 08/17/2013

Associated revisions

Revision 45600789 (diff)
Added by Loïc Dachary about 10 years ago

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 <>
Signed-off-by: Loic Dachary <>

Revision 3f5fc965 (diff)
Added by Loïc Dachary about 10 years ago

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 <>
Signed-off-by: Loic Dachary <>
(cherry picked from commit 45600789f1ca399dddc5870254e5db883fb29b38)

Revision f5668b36 (diff)
Added by Loïc Dachary about 10 years ago

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 <>
Signed-off-by: Loic Dachary <>
(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

#8 Updated by Loïc Dachary about 10 years ago

  • % Done changed from 80 to 90

#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)

Also available in: Atom PDF