Bug 1096155

Reproduced this bug with rsyslog7-mmopenshift-7.4.7-5.5.el6op.x86_64 and current OSE 2.1.1

For more context on what is being cached here... the mmopenshift module caches the app uuid and gear uuid in-memory to avoid having to read .env/OPENSHIFT* files with every log entry. This cache is supposed to be cleared out if the gear gets destroyed so that it can be re-read when a gear with the same UID is created. Apparently that's not happening.

Good catch, by the way.

Attaching a debug log from rsyslog7 where I ssh into an existing gear (ensuring the cache gets populated), destroy the gear, then attempt to create another (this seems to consistently fail while running in debug mode, not sure why, but that's a different issue).

Notice "delete event" never comes up with a UID:
5243.599599559:7fb038b3c700: mmopenshift: delete event
5243.599601124:7fb038b3c700: mmopenshift: delete directory
5243.599602982:7fb038b3c700: mmopenshift: trying to remove 5395c862e659c55b08000090 from uuidMap
5243.599605534:7fb038b3c700: mmopenshift: removed uid was NULL

I'm wondering if maybe uuidMap isn't being populated properly in the first place?

Created attachment 904757 [details]
rsyslog7 debug log

rsyslog7 debug log during population of u{,u}idMap cache, deletion of gear, and creation of another with same UID.

Possibly related but probably not: at https://github.com/openshift/enterprise-server/blob/enterprise-2.1/rsyslog-plugin/mmopenshift/mmopenshift.c#L649 it should be checking if pData->uuidMap is null (not pData->uidMap) otherwise there's no warning if uuidMap didn't get created for some reason. Might as well do that too if there's something else that needs to be fixed for this bug.

The watchThread is currently being created prior to fork() being called, and after fork, the thread is killed along with the parent process. It needs to be created post fork(). This is not a simple task, unfortunately, and I'm looking into options.

1 workaround for now would be to modify /etc/init.d/rsyslog7 to add the "-n" flag to rsyslog7 (don't fork) and background it.

Not sure if this is what you meant:

#daemon --pidfile="$PIDFILE" $exec -i "$PIDFILE" -M /lib64/rsyslog7 -f /etc/rsyslog7.conf $SYSLOGD7_OPTIONS
=>
nohup $exec -i "$PIDFILE" -M /lib64/rsyslog7 -f /etc/rsyslog7.conf -n $SYSLOGD7_OPTIONS >> /var/log/messages &

However this doesn't seem to solve it for me; openshift_gears entries still refer to earlier cached gear info.

I'm working on a fix that creates the watchThread after rsyslog7 calls fork(). See https://github.com/ncdc/origin-server/commit/7c5633d4ec6b5d7d49f43e2fde946e41b4298521 for details.

Testing it on a fresh OSE 2.1 VM with selinux-policy-3.7.19-231.el6_5.3, I'm seeing a new AVC I didn't see before:

time->Wed Jun 11 15:53:06 2014
type=SYSCALL msg=audit(1402516386.822:12778): arch=c000003e syscall=0 success=yes exit=48 a0=4 a1=7f2d2fcbac60 a2=110 a3=0 items=0 ppid=1 pid=11964 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts0 ses=2 comm=72733A6D61696E20513A526567 exe="/sbin/rsyslogd7" subj=unconfined_u:system_r:syslogd_t:s0 key=(null)
type=AVC msg=audit(1402516386.822:12778): avc:  denied  { read } for  pid=11964 comm=72733A6D61696E20513A526567 path="inotify" dev=inotifyfs ino=1 scontext=unconfined_u:system_r:syslogd_t:s0 tcontext=system_u:object_r:inotifyfs_t:s0 tclass=dir

Assuming we want to go with the patch above, we'll need to file a separate bug and link it to this one for the selinux policy issue.

My testing of the rebuilt pkg indicates this succeeds if combined with the following selinux rules:

module rsyslog7-mmopenshift 1.0;

require {
        type syslogd_t;
        type inotifyfs_t;
        class dir read;
}

#============= syslogd_t ==============
# enable rsyslog7-mmopenshift to receive inotify events so that when 
# a gear is removed, the cached context for its UID can also be removed.
allow syslogd_t inotifyfs_t:dir read;


If this is not done, then clearing the cache doesn't occur and this bug persists (but no other adverse effect is seen).

origin-server commits (including for BZ searchability) are:


commit 873f9b838b6906b01dd1eb257c41e273a72a9e3b
Author: Andy Goldstein <agoldste>
Date:   Tue Jun 10 14:46:11 2014 -0400

    Add missing commit to match rsyslog7-7.4.7-5.5


commit 7c5633d4ec6b5d7d49f43e2fde946e41b4298521
Author: Andy Goldstein <agoldste>
Date:   Wed Jun 11 15:20:09 2014 -0400

    Create watchThread after rsyslog forks
    
    Move creation of the watchThread to after rsyslog forks, so the thread
    isn't terminating when the fork happens.
    
    Fixes bug 1096155

check on puddle [2.1.z/2014-07-07.1]
1.Delete capacity from district to make user the two apps have the same uid
#oo-admin-ctl-district -c remove-capacity -n medium -s 5999
2.configure the logshifter
#vim /etc/openshift/logshifter.conf
<--snip-->
outputtype = syslog
<--snip-->
3.configure the rsyslog appropriately to enable mmopenshift
#cat /etc/rsyslog7.conf
module(load="imuxsock" SysSock.Annotate="on" SysSock.ParseTrusted="on" SysSock.UsePIDFromSystem="on")
   
    template(name="OpenShift" type="list") {
        property(name="timestamp" dateFormat="rfc3339")
        constant(value=" ")
        property(name="hostname")
        constant(value=" ")
        property(name="$!all-json")
        constant(value=" ")
        property(name="syslogtag")
        constant(value=" app=")
        property(name="$!OpenShift!OPENSHIFT_APP_UUID")
        constant(value=" gear=")
        property(name="$!OpenShift!OPENSHIFT_GEAR_UUID")
        constant(value=" ns=")
        property(name="$!OpenShift!OPENSHIFT_NAMESPACE")
        property(name="msg" spifno1stsp="on")
        property(name="msg" droplastlf="on")
        constant(value="\n")
    }
   
    module(load="mmopenshift" gearuidstart="1000" gearbasedir="/var/lib/openshift" maxcachesize="10")
    action(type="mmopenshift")
    if $!OpenShift!OPENSHIFT_APP_UUID != '' then
    *.* action(type="omfile" file="/var/log/openshift_gears" template="OpenShift")
    else {
    *.info;mail.none;authpriv.none;cron.none      action(type="omfile" file="/var/log/messages")
    }
4.start the rsyslog7
#service rsyslog stop
#service rsyslog7 restart
5.create an app 
#rhc app create testapp php-5.3
6.check the log
#tailf /var/log/openshift_gears 
7.delete the app, and create it again
#rhc app delete testapp --confirm; rhc app create phpapp php-5.3
8.check the log again
#tailf /var/log/openshift_gears 

Output:
2014-07-07T23:57:44.356328-07:00 broker { "pid": 5698, "uid": 1000, "gid": 1000, "OpenShift": { "OPENSHIFT_GEAR_UUID": "53bb965c08c29109a7000693", "OPENSHIFT_APP_UUID": "53bb965c08c29109a7000693", "OPENSHIFT_NAMESPACE": "xiaom", "OPENSHIFT_APP_NAME": "phpapp" } } php[5698]: app=53bb965c08c29109a7000693 gear=53bb965c08c29109a7000693 ns=xiaom [Mon Jul 07 23:57:44 2014] [notice] Apache/2.2.15 (Unix) configured -- resuming normal operations

2014-07-07T23:58:08.874824-07:00 broker { "pid": 7081, "uid": 1000, "gid": 1000, "OpenShift": { "OPENSHIFT_GEAR_UUID": "53bb965c08c29109a7000693", "OPENSHIFT_APP_UUID": "53bb965c08c29109a7000693", "OPENSHIFT_NAMESPACE": "xiaom", "OPENSHIFT_APP_NAME": "phpapp" } } php[7081]: app=53bb965c08c29109a7000693 gear=53bb965c08c29109a7000693 ns=xiaom [Mon Jul 07 23:58:08 2014] [notice] SELinux policy enabled; httpd running as context unconfined_u:system_r:openshift_t:s0:c0,c1000

The two applications have the same UUID.

SELinux policy update is required in order for the fix to work.

This can be done manually for now as per https://github.com/openshift/openshift-extras/pull/398/files

1.Install the selinux-policy
#rpm -qa|grep selinux-policy
selinux-policy-3.7.19-241.el6.noarch
selinux-policy-targeted-3.7.19-241.el6.noarch
selinux-policy-mls-3.7.19-241.el6.noarch
2.Delete capacity from district to make user the two apps have the same uid
#oo-admin-ctl-district -c remove-capacity -n medium -s 5999
3.create an app 
#rhc app create testapp php-5.3
4.delete the app, and create it again
#rhc app delete testapp --confirm; rhc app create phpapp php-5.3
5.check the log 
#tailf /var/log/openshift_gears 
Output:
Jul  8 19:23:32 broker php[7844]: app=phpapp ns=xiaom appUuid=53bca79808c2913be80003ae gearUuid=53bca79808c2913be80003ae [Tue Jul 08 19:23:32 2014] [notice] Apache/2.2.15 (Unix) configured -- resuming normal operations
Jul  8 19:26:22 broker php[10433]: app=phpapp ns=xiaom appUuid=53bca84308c2913be80003ce gearUuid=53bca84308c2913be80003ce [Tue Jul 08 19:26:22 2014] [notice] SELinux policy enabled; httpd running as context unconfined_u:system_r:openshift_t:s0:c0,c1000

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.

http://rhn.redhat.com/errata/RHBA-2014-0878.html