Bug 815887 - nanny: no information logged when sorry_server defined
nanny: no information logged when sorry_server defined
Status: CLOSED ERRATA
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: piranha (Show other bugs)
6.4
All Linux
high Severity medium
: rc
: ---
Assigned To: Ryan O'Hara
Cluster QE
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-04-24 14:12 EDT by Ryan O'Hara
Modified: 2012-06-20 10:18 EDT (History)
3 users (show)

See Also:
Fixed In Version: piranha-0.8.5-18.el6
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-06-20 10:18:14 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
Allow nanny to write to syslog when --nodaemon option is specified. (1.09 KB, patch)
2012-04-24 16:21 EDT, Ryan O'Hara
no flags Details | Diff
Call openlog whenever LVS_FLAG_SYSLOG is set (2.35 KB, patch)
2012-04-25 16:35 EDT, Ryan O'Hara
no flags Details | Diff

  None (edit)
Description Ryan O'Hara 2012-04-24 14:12:33 EDT
When no sorry_server is defined is lvs.cf, nanny will log information to syslog correctly. When a sorry_server is defined, no information is logged.

Consider a piranha configuration with a single virtual server and two real servers. Test is to simply start/stop the pulse service and watch messages in /var/log/messages.

Without a sorry_server defined, /var/log/messages will show the creation of each nanny process. Note that the nanny processes also write to syslog.

# service pulse start
Starting pulse:                                            [  OK  ]

Apr 24 12:47:01 node-06 lvs[4999]: starting virtual service VIP_201 active: 80
Apr 24 12:47:01 node-06 lvs[4999]: create_monitor for VIP_201/mobil-virt-08 running as pid 5009
Apr 24 12:47:01 node-06 lvs[4999]: create_monitor for VIP_201/mobil-virt-09 running as pid 5010
Apr 24 12:47:01 node-06 nanny[5009]: starting LVS client monitor for 192.168.1.201:80 -> 192.168.1.108:80
Apr 24 12:47:01 node-06 nanny[5010]: starting LVS client monitor for 192.168.1.201:80 -> 192.168.1.109:80
Apr 24 12:47:01 node-06 nanny[5009]: [ active ] making 192.168.1.108:80 available
Apr 24 12:47:01 node-06 nanny[5010]: [ active ] making 192.168.1.109:80 available

# service pulse stop
Shutting down pulse:                                       [  OK  ]

Apr 24 12:50:04 node-06 pulse[4997]: Terminating due to signal 15
Apr 24 12:50:04 node-06 lvs[4999]: shutting down due to signal 15
Apr 24 12:50:04 node-06 lvs[4999]: shutting down virtual service VIP_201
Apr 24 12:50:04 node-06 nanny[5009]: Terminating due to signal 15
Apr 24 12:50:04 node-06 nanny[5010]: Terminating due to signal 15

With a sorry_server defined, /var/log/messages does not show any information being logged from the nanny processes.

# service pulse start
Starting pulse:                                            [  OK  ]

Apr 24 12:50:29 node-06 lvs[5059]: starting virtual service VIP_201 active: 80
Apr 24 12:50:29 node-06 lvs[5059]: create_monitor for VIP_201/mobil-virt-08 running as pid 5069
Apr 24 12:50:29 node-06 lvs[5059]: create_monitor for VIP_201/mobil-virt-09 running as pid 5070

But clearly nanny processes are running as expected:

# ps -ef|grep nanny
root      5069  5059  0 12:50 ?        00:00:00 /usr/sbin/nanny -c -h 192.168.1.108 -p 80 -r 80 -s GET / HTTP/1.0\r\n\r\n -x HTTP -a 15 -I /sbin/ipvsadm -t 6 -w 1 -V 192.168.1.201 -M g -U none --nodaemon --lvs
root      5070  5059  0 12:50 ?        00:00:00 /usr/sbin/nanny -c -h 192.168.1.109 -p 80 -r 80 -s GET / HTTP/1.0\r\n\r\n -x HTTP -a 15 -I /sbin/ipvsadm -t 6 -w 1 -V 192.168.1.201 -M g -U none --nodaemon --lvs

# service pulse stop
Shutting down pulse:                                       [  OK  ]

Apr 24 13:09:43 node-06 pulse[5057]: Terminating due to signal 15
Apr 24 13:09:43 node-06 lvs[5059]: shutting down due to signal 15
Apr 24 13:09:43 node-06 lvs[5059]: shutting down virtual service VIP_201
Comment 4 Ryan O'Hara 2012-04-24 16:21:35 EDT
Created attachment 579988 [details]
Allow nanny to write to syslog when --nodaemon option is specified.

When a sorry_server is defined, lvsd will start nanny with the --nodaemon option. This caused nanny to not write information to syslog. This problem is a result of two problems in the code:

1. The LVS_FLAG_SYSLOG was not being set when --nodaemon was specified.\
2. The piranha_log function would write log messages to stdout or syslog, but not both.

This patch fixes both of these problems. Note that the va_start and va_end must be moved into each if block in order to avoid segfault.
Comment 6 Ryan O'Hara 2012-04-24 16:27:28 EDT
Test results with patch provided in comment #4:

# grep sorry_server /etc/sysconfig/ha/lvs.cf 
     sorry_server = 192.168.1.101

# service pulse start
Starting pulse:                                            [  OK  ]

From /var/log/messages ...

Apr 24 15:09:27 node-06 lvs[6426]: starting virtual service VIP_201 active: 80
Apr 24 15:09:27 node-06 lvs[6426]: create_monitor for VIP_201/mobil-virt-08 running as pid 6436
Apr 24 15:09:27 node-06 lvs[6426]: create_monitor for VIP_201/mobil-virt-09 running as pid 6437
Apr 24 15:09:27 node-06 nanny: starting LVS client monitor for 192.168.1.201:80 -> 192.168.1.109:80
Apr 24 15:09:27 node-06 nanny: starting LVS client monitor for 192.168.1.201:80 -> 192.168.1.108:80
Apr 24 15:09:27 node-06 nanny: [ active ] making 192.168.1.108:80 available
Apr 24 15:09:27 node-06 nanny: [ active ] making 192.168.1.109:80 available

This is correct.
Comment 10 Ryan O'Hara 2012-04-25 16:35:59 EDT
Created attachment 580274 [details]
Call openlog whenever LVS_FLAG_SYSLOG is set

Currently, openlog is called within the daemonize function. Since defining a sorry_server in lvs.cf causes nanny to be called with the --nodaemon option, daemonize will not be called and therefore openlog will not be called, regardless of LVS_FLAG_SYSLOG. While it is perfectly acceptable to call syslog without calling openlog first, you'll noticed that messages logged from nanny will not report the pid since openlog was not called with LOG_PID option.

Solution is to call openlog outside of daemonize. This patch removes openlog from daemonize and calls openlog directly from each process is LVS_FLAG_SYSLOG is set.
Comment 11 Ryan O'Hara 2012-04-25 16:40:16 EDT
With only patch from comment #4 and lvs.cf where sorry_server is defined, openlog is not called so log messages from nanny will not have pid included:

Apr 25 11:43:17 node-06 nanny: [ active ] making 192.168.1.108:80 available
Apr 25 11:43:17 node-06 nanny: [ active ] making 192.168.1.109:80 available

With patch from comment #10, openlog is always called is LVS_FLAG_SYSLOG and regardless if process calls daemonize. Note that the pid is included in each message.

Apr 25 15:02:28 node-06 nanny[8173]: [ active ] making 192.168.1.109:80 available
Apr 25 15:02:28 node-06 nanny[8172]: [ active ] making 192.168.1.108:80 available
Comment 14 errata-xmlrpc 2012-06-20 10:18:14 EDT
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-2012-0891.html

Note You need to log in before you can comment on or make changes to this bug.