Incorrect remote logs symlinks on master node lead to deployment failure after several redeployments

Iryna, please provide diagnostic snapshot.

Please find logs on google drive:
https://drive.google.com/a/mirantis.com/file/d/0B4E4dXThZYVDN2dQd1FYSFVEMm8/view?usp=sharing

We need to fix it ASAP due the importance. On of our customer need Contrail plugin on 2 weeks. So i put status as Critical

I think problem starts here:

Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/nailgun/utils/__init__.py", line 47, in remove_silently
    shutil.rmtree(path)
  File "/usr/lib64/python2.6/shutil.py", line 212, in rmtree
    rmtree(fullname, ignore_errors, onerror)
  File "/usr/lib64/python2.6/shutil.py", line 221, in rmtree
    onerror(os.rmdir, path, sys.exc_info())
  File "/usr/lib64/python2.6/shutil.py", line 219, in rmtree
    os.rmdir(path)
OSError: [Errno 39] Directory not empty: '/var/log/remote/10.20.0.51/bootstrap'

It can be problem with race condition.

We handle exception in case of shutil.rmtree https://github.com/stackforge/fuel-web/blob/stable/6.1/nailgun/nailgun/utils/__init__.py#L41-L49 but not for symlink https://github.com/stackforge/fuel-web/blob/stable/6.1/nailgun/nailgun/utils/logs.py#L81.

We passed SCF in 8.0. Moving the bug to 9.0.

(This check performed automatically)
Please, make sure that bug description contains the following sections filled in with the appropriate data related to the bug you are describing:

expected result

For more detailed information on the contents of each of the listed sections see https://wiki.openstack.org/wiki/Fuel/How_to_contribute#Here_is_how_you_file_a_bug

Tricky issue with low reproducibility and known workaround. Moving to 10.0.

Workaround: remove broken symlinks in /var/log/remote directory.

Here is root cause analysis from duplicate bug:

The error can occur if master node aperates slowly.

In this case it can execute code from

nailgun/nailgun/utils/logs.py

    # rename bootstrap directory into fqdn
    if os.path.islink(old):
        logger.debug("Old %s exists and it is link. "
                     "Trying to unlink", old)
        os.unlink(old)
    if os.path.isdir(old):
        logger.debug("Old %s exists and it is directory. "
                     "Trying to rename into %s", old, new)
        os.rename(old, new)
    else:
        logger.debug("Creating %s", new)
        os.makedirs(new)

    # creating symlinks
    for l in links:
        if os.path.islink(l) or os.path.isfile(l):
            logger.debug("%s already exists. "
                         "Trying to unlink", l)
            os.unlink(l)
        if os.path.isdir(l):
            logger.debug("%s already exists and it directory. "
                         "Trying to remove", l)
            shutil.rmtree(l)
---------------------
Then syslog server continues receiving messaqges from node, it recreates missing <ip>/bootstrap directory and writes some files there. Then nailgun process continues
------------------------
        logger.debug("Creating symlink %s -> %s", l, new)
        os.symlink(objects.Node.get_node_fqdn(node), l) <<<<<<<<<<<<<<< error!

Fix proposed to branch: master
Review: https://review.openstack.org/318544

Reviewed: https://review.openstack.org/318544
Committed: https://git.openstack.org/cgit/openstack/fuel-web/commit/?id=6e49910fcadf52cdeff235b0795f0dde2f63f60a
Submitter: Jenkins
Branch: master

commit 6e49910fcadf52cdeff235b0795f0dde2f63f60a
Author: Dmitry Guryanov <email address hidden>
Date: Thu May 19 12:14:56 2016 +0300

    fix race with syslog while renaming remote log dir

    When a node gets new name nailgun renmaes log directoty
    which had name in for mof <IP> to <node name> and then
    creates symlink <IP> -> <node name>. The problem is that
    node is still active and this moment and sends some logs
    to syslog on master node.

    So when we renamed <IP> to <node name> and haven't created
    symlink name syslog may find missing log dir and it creates
    it again in this case. Then nailgun tries to create symlink
    and fails.

    To avoid this situation we can suspend rsyslog temporarity.
    It's better to do it with SIGSTOP/SIGCONT, because process
    exist in this case and remote logs will be held in kernel
    tcp or odp buffers until we wake up rsyslog and it process
    new messages. Fortunately centos-7 uses journald together
    with rsyslog, so local logs (send by syslog function) are
    handled by journald and rsyslog just get it from journald
    files. So it's safe to stop rsyslog temporarily, nothing
    will be droppped.

    Change-Id: Icb1ed6669be2f7b448c465de33de37e0b945fb79
    Closes-Bug: #1506112

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/323193

ETA: 03.06.2016

Reviewed: https://review.openstack.org/323193
Committed: https://git.openstack.org/cgit/openstack/fuel-web/commit/?id=019ad234af0f8344102d3342587312a7ec5256fa
Submitter: Jenkins
Branch: stable/mitaka

commit 019ad234af0f8344102d3342587312a7ec5256fa
Author: Dmitry Guryanov <email address hidden>
Date: Thu May 19 12:14:56 2016 +0300

    fix race with syslog while renaming remote log dir

    When a node gets new name nailgun renmaes log directoty
    which had name in for mof <IP> to <node name> and then
    creates symlink <IP> -> <node name>. The problem is that
    node is still active and this moment and sends some logs
    to syslog on master node.

    So when we renamed <IP> to <node name> and haven't created
    symlink name syslog may find missing log dir and it creates
    it again in this case. Then nailgun tries to create symlink
    and fails.

    To avoid this situation we can suspend rsyslog temporarity.
    It's better to do it with SIGSTOP/SIGCONT, because process
    exist in this case and remote logs will be held in kernel
    tcp or odp buffers until we wake up rsyslog and it process
    new messages. Fortunately centos-7 uses journald together
    with rsyslog, so local logs (send by syslog function) are
    handled by journald and rsyslog just get it from journald
    files. So it's safe to stop rsyslog temporarily, nothing
    will be droppped.

    Change-Id: Icb1ed6669be2f7b448c465de33de37e0b945fb79
    Closes-Bug: #1506112
    (cherry picked from commit 6e49910fcadf52cdeff235b0795f0dde2f63f60a)

Fix proposed to branch: stable/8.0
Review: https://review.openstack.org/330993

Since it's hard to reproduce the problem (it's a race), I've checked code, and the patch is there.

Change abandoned by Rodion Tikunov (<email address hidden>) on branch: stable/8.0
Review: https://review.openstack.org/330993
Reason: Approach used in this patch does not work in <=8.0. In MOS=<8.0 nailgun works in docker container and can not communicate by signals with rsyslog which works in another container

Fix proposed to branch: stable/8.0
Review: https://review.openstack.org/332001

Steps to reproduce:
1) Configure cluster with 1 controller and 1 compute nodes
2) In nailgun container change modify file /usr/lib/python2.7/site-packages/nailgun/utils/logs.py by adding time.sleep(10) before os.symlink(objects.Node.get_node_fqdn(node), l)
3) rm /usr/lib/python2.7/site-packages/nailgun/utils/logs.py[oc]
4) touch /var/lib/nailgun-uwsgi - after that new logs.pyc should be created
5) On nodes (which in bootstrap stage) start to create extensive log traffic:
while true; do
    logger -t nailgun-agent "test123 tCDqdvB2+xbeYNU68n3Xd6q08kDZLdtFTz57xfTKn53icDSWr6gVm3SP842938jf908j098js9djf9sjdf9sj9jjjeroiwjroij8934nkjnwlkjrhf87f78hf3n4f24no2h478shf8shd8hfsdfhsd78w7y9r7hwe8rhwohrefw879erhf897werhf98w7hresiojoidjfviusj+0NBQIlFXpqpqdIEXA15 `date`";
done
6) Deploy cluster

Won't Fix for 6.1-updates because 6.1 is in Limited support now

Fix proposed to branch: stable/7.0
Review: https://review.openstack.org/367245

Reviewed: https://review.openstack.org/332001
Committed: https://git.openstack.org/cgit/openstack/fuel-web/commit/?id=11ce99ab4e46fad061edd99c6342ea647f0acd75
Submitter: Jenkins
Branch: stable/8.0

commit 11ce99ab4e46fad061edd99c6342ea647f0acd75
Author: Rodion Tikunov <email address hidden>
Date: Mon Jun 20 18:48:12 2016 +0300

    fix race with syslog while renaming remote log dir

    When a node gets new name nailgun renames log directory which had name
    in form of <IP> to <node name> and then creates symlink <IP> ->
    <node name>. The problem is that node is still active at this moment
    and sends some logs to syslog on master node. So when we renamed <IP>
    to <node name> and haven't created symlink name syslog may find
    missing log dir and it creates it again in this case. Then nailgun
    tries to create symlink and fails.

    To avoid this situation this patch adds attempts to remove a directory
    and create symlink until symlink will being successfully created.

    Approach used in master does not work in <=8.0. In MOS=<8.0 nailgun
    and rsyslog work in different PID namespaces and can not interact
    with each other by signals.

    Change-Id: Ia402508dac427909aa1593787f9aba54f2df05e4
    Closes-bug: #1506112

Reviewed: https://review.openstack.org/367245
Committed: https://git.openstack.org/cgit/openstack/fuel-web/commit/?id=b1da633fdac0f9eab6ee05d902dfbd3e9d57be05
Submitter: Jenkins
Branch: stable/7.0

commit b1da633fdac0f9eab6ee05d902dfbd3e9d57be05
Author: Rodion Tikunov <email address hidden>
Date: Mon Jun 20 18:48:12 2016 +0300

    fix race with syslog while renaming remote log dir

    When a node gets new name nailgun renames log directory which had name
    in form of <IP> to <node name> and then creates symlink <IP> ->
    <node name>. The problem is that node is still active at this moment
    and sends some logs to syslog on master node. So when we renamed <IP>
    to <node name> and haven't created symlink name syslog may find
    missing log dir and it creates it again in this case. Then nailgun
    tries to create symlink and fails.

    To avoid this situation this patch adds attempts to remove a directory
    and create symlink until symlink will being successfully created.

    Approach used in master does not work in <=8.0. In MOS=<8.0 nailgun
    and rsyslog work in different PID namespaces and can not interact
    with each other by signals.

    Change-Id: Ia402508dac427909aa1593787f9aba54f2df05e4
    Closes-bug: #1506112
    (cherry picked from commit 11ce99ab4e46fad061edd99c6342ea647f0acd75)

Verified on MOS 7.0 + MU6 updates using steps from [0].

Before updates bug was reproduced - deployment has failed with error "[Errno 17] File exists".
After updates deployment has finished successfully.

[0] https://bugs.launchpad.net/fuel/+bug/1506112/comments/20

Verified on MOS 8.0 + MU4 updates.

Actual results:
Before updates bug was reproduced - deployment has failed with error "[Errno 17] File exists".
After updates deployment has finished successfully.