Bug 1302675

Boris, could you please look into this bug? I will try reproducing it.

I suppose what happened here is that ceph-deploy has got way too low a time-out value for this command to run its post install script successfully. Afterwards, ceph-deploy will kill the remote command somewhere in the middle leaving the machine in an inconsistent state -- we do stop mon/osd in the post script for relabel. Your machine should be ok if you simply bring the osd back up again on the remote machine (you might also need to relabel the ceph-related directories, though).

Generally, it is easy for almost any installation command to take more than 5 minutes. Given that we can do a relabel of quite a huge amount of data, the install procedure can take probably even hours for it to complete in case of ceph-selinux package.

-> re-targeting to ceph-deploy

i.e.: the suggested solution is much higher time-out value for ceph-deploy pkg --install remote commands

When ceph-deploy closes the connection it doesn't `kill` the remote command/process: it just disconnects.

If an OSD is getting marked down when installing selinux, it certainly cannot be because of ceph-deploy disconnecting after 300 seconds.

To demonstrate that the command will still hold (specifically running yum):

    $ ipython
    Python 2.7.8 (v2.7.8:ee879c0ffa11, Jun 29 2014, 21:07:35)
    Type "copyright", "credits" or "license" for more information.
    
    IPython 4.0.1 -- An enhanced Interactive Python.
    ?         -> Introduction and overview of IPython's features.
    %quickref -> Quick reference.
    help      -> Python's own help system.
    object?   -> Details about 'object', use 'object??' for extra details.
    
    In [1]: from ceph_deploy import hosts
    
    In [2]: distro = hosts.get('node6')
    
    # Close the connection after one second
    In [3]: distro.conn.global_timeout = 1
    
    # Install 'vim' on the remote node (node6 in this case)
    In [4]: distro.packager.install(['vim'])
    
    
    # Now ssh into node6 and see if yum is running, the ipython session above is now
    # closed (this is the same terminal session)

    (ceph-deploy)papaya-2[master] ..ream/ceph-deploy/ceph_deploy $ ssh node6
    Last login: Fri Jan 29 20:11:21 2016 from 192.168.111.1
    Welcome to your Packer-built virtual machine.
    [vagrant@localhost ~]$ ps aux | grep yum
    root      3890  1.3  4.5 421152 23028 ?        Sl   12:34   0:00 /usr/bin/python /bin/yum -y install vim
    vagrant   3918  0.0  0.1 112640   968 pts/0    R+   12:34   0:00 grep --color=auto yum
    [vagrant@localhost ~]$ which vim
    /usr/bin/which: no vim in (/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/home/vagrant/.local/bin:/home/vagrant/bin)
    [vagrant@localhost ~]$ date
    Mon Feb  1 12:34:37 UTC 2016
    
    # yum is still installing vim. Let's wait and see if it completes


    [vagrant@localhost ~]$ ps aux | grep yum
    root      3890  0.5  5.1 429520 26028 ?        Sl   12:34   0:00 /usr/bin/python /bin/yum -y install vim
    vagrant   3929  0.0  0.1 112640   968 pts/0    R+   12:35   0:00 grep --color=auto yum
    [vagrant@localhost ~]$ date
    Mon Feb  1 12:35:06 UTC 2016

    # still going after a minute
    
    [vagrant@localhost ~]$ ps aux | grep yum
    vagrant   4012  0.0  0.1 112640   968 pts/0    R+   12:36   0:00 grep --color=auto yum
    [vagrant@localhost ~]$ date
    Mon Feb  1 12:36:36 UTC 2016
    [vagrant@localhost ~]$ which vim
    /usr/bin/vim

    # completed after about 2 minutes


There is no easy way I can think of where ceph-deploy can detect if in fact a remote command that is running is stuck/hung or if it should just wait.

If a higher timeout would be set, we would undoubtedly hit a similar problem for a larger system that may have a slow network for example.

But then again, I highly doubt this is a problem with ceph-deploy. Rule of thumb for ceph-deploy issues is to try and execute the same command ceph-deploy is running remotely and see if the same behavior persists or not.

I'm not 100% sure that yum will continue like that in all cases if you terminate the SSH connection. I know it worked for Vim above, but I've seen it fail midway on other packages. One example is the kernel RPM, which has a long-running %post task (regenerating initrd). I've broken systems before when I was yum-updating a kernel package and lost my SSH connection. It strikes me as similar to the long-running ceph-selinux %post task.

Boris, should we change the documentation here to avoid "ceph-deploy pkg --install ceph-selinux", and have the users just run the "yum install" command by hand on each node ?

Created attachment 1120295 [details]
Increase timeout for pkg install procedure patch

We can fix this in code if we try to increase the default timeout value for 'ceph-deploy pkg --install' commands. I'll send the patch upsream some time tomorrow (well, later today for me). In the meantime it would be nice if this actually got reviewed, i.e. to be more sure that the timeout kw argument actually gets propagated to the remoto.run statement, etc.

Hm, sorry, completely missed alfredo's comment:

My other guess would then be that while the yum process did not get killed, it did not complete either so the yum was still running and the osd was still down. It should be brought up automatically after a while unless you powered off the machine. This would be quite easy to check by steps described in Alfredo's comment (simply connect to the machine and check that the yum process is still running).

Either way, we should be able to fix this for the user if we increase the timeout value. As for the exact safe value, I myself would wonder how long can a file system relabel take on a really huge production system. Hopefully, the 5 hours that I used should be long enough.

From what I can see here

http://pydoc.net/Python/remoto/0.0.16/remoto.log/

we should be able to use timeout=-1 to wait forever so I'd suggest using that for the 'ceph-deploy pkg --install' command instead of the ~random 5 hour long maximal wait.

There is in fact some possibility that disconnecting early may be causing this.

However, it is critical to determine if that is the case. To verify this as a bug that requires a change in ceph-deploy we need to make sure that:

* installing ceph-selinux on the actual server via yum (sans ceph-deploy) works correctly, not marking OSDs down

Created attachment 1120401 [details]
Disable timeout for pkg install/remove patch

OK, after some testing, the value of -1 won't help here. The timeout value has to be None for execnet (which remoto uses) to wait forever. However, you can't simply do timeout = None (*) if you have a non-None global_timeout. However, you can temporarily disable global_timeout in the install function to enable "wait forever" mode.

(*) not to mention that it wouldn't propagate all the way from that line as I recently found out but that could be quite easily patched

@Alfredo: We do stop osd services in ceph-selinux post script when we do relabel so it is no surprise that the OSD is down while yum is still running in the background. The same would go for MON if you checked the health of the cluster while yum is still running ceph-selinux post script. However, we also start the processes (restore them to their original state) once the relabelling procedure completes. This was also verified for MONs where it worked just fine. It is just the timeout that confuses the users in this case.

Upstream PR:

https://github.com/ceph/ceph-deploy/pull/384

dist-git commits related to build ceph-deploy-1.5.27.4-2.el7cp:
http://pkgs.devel.redhat.com/cgit/rpms/ceph-deploy/commit/?h=ceph-1.3-rhel-7&id=3195d69b0996a4f7da0c6006b9880b17e2c07b76

Strangely, again it happened almost same thing.
The installation got stuck for a while and then the OSD was marked Down, one-by-one.

But after sometime, the OSD again came back UP and the installation process completed.

But for a while all the OSD daemon went DOWN one-by-one

ceph-common-0.94.5-8.el7cp.x86_64
ceph-0.94.5-8.el7cp.x86_64
ceph-selinux-0.94.5-8.el7cp.x86_64
ceph-osd-0.94.5-8.el7cp.x86_64

OSD Log Snippet:

Attaching one of the OSD log ( which got down when the installation process was in progress)


----------------------------------------------------------------------------

2016-02-07 02:48:35.841584 7f22db9aa7c0  0 ceph version 0.94.5-8.el7cp (deef183a81111fa5e128ec88c90a32c9587c615d), process ceph-osd, pid 16370
2016-02-07 02:48:35.866872 7f22db9aa7c0  0 filestore(/var/lib/ceph/osd/ceph-0) backend xfs (magic 0x58465342)
2016-02-07 02:48:35.911979 7f22db9aa7c0  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-0) detect_features: FIEMAP ioctl is supported and appears to work
2016-02-07 02:48:35.911987 7f22db9aa7c0  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-0) detect_features: FIEMAP ioctl is disabled via 'filestore fiemap' config option
2016-02-07 02:48:36.850460 7f22db9aa7c0  0 genericfilestorebackend(/var/lib/ceph/osd/ceph-0) detect_features: syncfs(2) syscall fully supported (by glibc and kernel)
2016-02-07 02:48:36.850592 7f22db9aa7c0  0 xfsfilestorebackend(/var/lib/ceph/osd/ceph-0) detect_feature: extsize is disabled by conf
2016-02-07 02:48:38.132515 7f22db9aa7c0  0 filestore(/var/lib/ceph/osd/ceph-0) mount: enabling WRITEAHEAD journal mode: checkpoint is not enabled
2016-02-07 02:48:38.418168 7f22db9aa7c0  1 journal _open /var/lib/ceph/osd/ceph-0/journal fd 19: 5367660544 bytes, block size 4096 bytes, directio = 1, aio = 1
2016-02-07 02:48:39.562723 7f22db9aa7c0  1 journal _open /var/lib/ceph/osd/ceph-0/journal fd 19: 5367660544 bytes, block size 4096 bytes, directio = 1, aio = 1
2016-02-07 02:48:39.563362 7f22db9aa7c0  0 <cls> cls/hello/cls_hello.cc:271: loading cls_hello
2016-02-07 02:48:39.569030 7f22db9aa7c0  0 osd.0 16466 crush map has features 283675107524608, adjusting msgr requires for clients
2016-02-07 02:48:39.569040 7f22db9aa7c0  0 osd.0 16466 crush map has features 283675107524608 was 8705, adjusting msgr requires for mons
2016-02-07 02:48:39.569046 7f22db9aa7c0  0 osd.0 16466 crush map has features 283675107524608, adjusting msgr requires for osds
2016-02-07 02:48:39.569059 7f22db9aa7c0  0 osd.0 16466 load_pgs
2016-02-07 02:48:41.023780 7f22db9aa7c0  0 osd.0 16466 load_pgs opened 889 pgs
2016-02-07 02:48:41.024637 7f22db9aa7c0 -1 osd.0 16466 log_to_monitors {default=true}
2016-02-07 02:48:41.028277 7f22c8d3f700  0 osd.0 16466 ignoring osdmap until we have initialized
2016-02-07 02:48:41.028373 7f22c8d3f700  0 osd.0 16466 ignoring osdmap until we have initialized
2016-02-07 02:48:43.059787 7f22db9aa7c0  0 osd.0 16466 done with init, starting boot process
2016-02-07 02:48:45.126297 7f22a5622700  0 -- 10.70.44.50:6801/16370 >> 10.70.44.50:6805/16541 pipe(0x11f21000 sd=121 :6801 s=0 pgs=0 cs=0 l=0 c=0x110f2000).accept connect_seq 0 vs existing 0 state connecting

Created attachment 1121688 [details]
Mon log

Created attachment 1121689 [details]
OSd log

That is nothing new. We do stop ceph daemons (both mon and osd) while the package is being installated to avoidhaving mislabelled files in the file system but we do bring them to their original state afterwards. It is not a bug, that is really an intended behaviour. We have already had an upstream discussion on that, here:

http://tracker.ceph.com/issues/13061

All we can fix here is to make ceph-deploy wait for the installation process to complete which we did (notice that the ceph-ceploy command did not time-out this time). Maybe, we should take special care to document it.

The reason why we have to wait so long is that we need to re-label a pretty big file system -- this means accessing a lot of files that Ceph has previously created (loads of disk reads) and changing their metadata (loads of disk writes). This does not happen every time the package is installed, only when new Ceph SELinux policy is detected and it is one of the reasons I pushed SELinux in 1.3.2 as an opt-in and not an opt-out.

btw: I wonder, how long did the installation process take on your test machine(s)? I heard it can take even more than an hour.

No it took 2-3 minutes of time and it didn't time out.

Documentation team:
Can this be documented in Installation guide saying that:

If the ceph-selinux package is installed later in ceph cluster, the ceph-selinux package installation can take time ( Time can be different based on the size of the cluster/objects/files) to complete its installation.

It will also reset the OSD/MON daemons, which means they will be stopped and started back again.

Boris,
Does the content look good, please modify if there is something needed to be changed/added,

Thanks,
Tanay

We should probably add more details and make it a bit more general like:


'All the Ceph daemons will be down for the time the ceph-selinux package is being installed. Therefore, your cluster will not be able to serve any data at this point.

This operation is necessary in order to update the metadata of the files located on the underlying file system and to make Ceph daemons run with the correct context.

This operation may easily take several minutes depending on the size and speed of the underlying storage.'

Hi Federico,

As per comment 18, the behavior observed in this bz can be documented.

Comment 20 has the doc text.

Please let us know if the doc text mentioned in comment 20 is fine with you.

We will move this BZ to doc team once you are ok with the doc text.

Thanks,
Harish

Very nicely done Boris. I agree, we need to doc this.

Let's add this to the docs *and* to the release notes.Outline is #comment #20.

NEEDINFO Anjana to decide where this goes in the docs.

Thanks Federico!

Moving this defect to assigned state.

Marking it as Verified, as the content is being added in the Installation Guide.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2016:0313