Bug 747984

Summary: RFE: need better log messages around init start/stop/failure
Product: [Retired] CloudForms Cloud Engine Reporter: Dave Johnson <dajohnso>
Component: iwhdAssignee: Pete Zaitcev <zaitcev>
Status: CLOSED WONTFIX QA Contact: Martin Kočí <mkoci>
Severity: low Docs Contact:
Priority: unspecified    
Version: 1.0.0CC: akarol, dajohnso, deltacloud-maint, dgao, hbrock, meyering, mkoci, morazi, ssachdev
Target Milestone: rcKeywords: FutureFeature
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Enhancement
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2012-08-15 16:04:40 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Dave Johnson 2011-10-21 15:37:56 UTC
Description of problem:
============================
This is a spin off of bug 740688...

When iwhd starts, the following is logged to its log file:
    0 replication servers defined
    Oct 21 11:31:11 iwhd[19191]: convert-provider: ITER key: name
    Oct 21 11:31:11 iwhd[19191]: convert-provider: ITER key: type
    Oct 21 11:31:11 iwhd[19191]: convert-provider: ITER key: path
    
    Can we get something like:
        Oct 21 11:31:11 iwhd[19191]: process starting up

When iwhd stops, nothing is logged, can we get something like:
    Oct 21 11:31:11 iwhd[19191]: process is shutting down

And when iwhd fails to start because mongod is down:
    Oct 21 11:31:11 iwhd[19191]: process starting up
    Oct 21 11:31:11 iwhd[19191]: process failed to start, mongod is unaccessible

Comment 1 Dave Johnson 2011-10-21 15:41:46 UTC
Also, this comment, https://bugzilla.redhat.com/show_bug.cgi?id=740688#c6, seems to indicate that if mongod goes down while warehouse is running, warehouse will stay up waiting for mongod to come back online. 

This circumstance needs to be logged as well, something like:
    Oct 21 11:31:11 iwhd[19191]: mongod service in inaccessible
    Oct 21 11:31:11 iwhd[19191]: mongod service in back online

Comment 2 Jim Meyering 2011-10-31 17:26:55 UTC
partially addressed (start/stop) by http://git.fedorahosted.org/git?p=iwhd.git;a=commitdiff;h=e24af06c38014e9bda0d4164f64de3f8b51d6a79, which is in iwhd-1.0

Comment 3 Martin Kočí 2011-11-08 09:13:53 UTC
Hi,
looks it doesn't work as expected for me against the latest available version on f16 : 

# /bin/iwhd --version
/bin/iwhd (iwhd) 1.0.1-1945

#service iwhd start
log output /var/log/iwhd.log: 
Initializing...
0 replication servers defined
Nov 08 09:21:55 iwhd[14268]: convert-provider: ITER key: name
Nov 08 09:21:55 iwhd[14268]: convert-provider: ITER key: type
Nov 08 09:21:55 iwhd[14268]: convert-provider: ITER key: path

#service iwhd stop
log output /var/log/iwhd.log: 
11 08 09:22:48 killed iwhd[]

If mongod is down then I'm not getting anything in the log.  

Moving bug to ON_DEV status.

Comment 4 Pete Zaitcev 2012-02-02 00:06:07 UTC
I do not understand... The iwhd reports that Mongo is down just fine here:

[root@lembas iwhd-tip]# systemctl start iwhd.service 
[root@lembas iwhd-tip]# tail /var/log/iwhd.log 
Initializing...
0 replication servers defined
Feb 01 17:03:01 iwhd[12039]: convert-provider: ITER key: name
Feb 01 17:03:01 iwhd[12039]: convert-provider: ITER key: type
Feb 01 17:03:01 iwhd[12039]: convert-provider: ITER key: path
Feb 01 17:03:01 iwhd[12039]: server down, no metadata access
[root@lembas iwhd-tip]# 

I noticed some small problems with Jim's fix:
 - [$pid] is empty, because on success pidfile is removed
 - "Initializing" should be log_msg() to get timestamp

I'm going to fix that up, but I think bug is fixed. Dave? Martin?

BTW:
[root@lembas iwhd-tip]# rpm -q iwhd
iwhd-1.2-1.fc16.x86_64

Comment 5 Martin Kočí 2012-02-02 08:54:07 UTC
ok, lemme check that with the latest version.

Comment 6 Martin Kočí 2012-02-02 12:10:14 UTC
So with iwhd-1.2-3.el6.x86_64 package it still works as is describe in description. When iwhd stops, nothing is logged, when is start then you get 

[root@qeblade ~]# tail /var/log/iwhd.log
Initializing...
0 replication servers defined
Feb 02 06:53:48 iwhd[25988]: convert-provider: ITER key: name
Feb 02 06:53:48 iwhd[25988]: convert-provider: ITER key: type
Feb 02 06:53:48 iwhd[25988]: convert-provider: ITER key: path

if mongod is stop then nothing is logged and output is:

# service mongod status
mongod is stopped
[root@qeblade22 iwhd]# service iwhd status
iwhd is stopped
[root@qeblade22 iwhd]# service iwhd start
waiting for mongod to listen on localhost:27017            [FAILED]
[root@qeblade22 iwhd]# rpm -q iwhd
iwhd-1.2-3.el6.x86_64

Let me know if you need further information.

Comment 7 Jim Meyering 2012-02-02 13:09:16 UTC
When mongod is not running, iwhd does not even start, so there is no
way the iwhd binary can log anything.  The init script detects that.
It waits for configurable MONGOD_N_SECONDS (default=2) for the mongod
server to start.  If mongod fails to start in time, the script
prints the "[FAILED]" diagnostic.

The current init script does this:

    wait_for_mongod $MONGOD_N_SECONDS && echo_success \
	|| { echo_failure; echo; return 1; }

it's easy to make it write an explanation to the log:

    wait_for_mongod $MONGOD_N_SECONDS && echo_success \
	|| { echo_failure; echo
	     echo "$(date '+%b %d %T') $PROCESS: failed to start:" \
	       "mongod is inaccessible" >> $IWHD_LOG_FILE
	     return 1; }

Comment 8 Jim Meyering 2012-02-02 17:17:06 UTC
IMHO, this isn't worth a release.  I suggest deferring to 1.1.

If someone disagrees, let me know ASAP.

Comment 9 Martin Kočí 2012-02-03 07:40:30 UTC
From QA point of view I'm OK with both releases.

Comment 10 Jim Meyering 2012-02-03 07:56:56 UTC
Thanks.  Moved to cloudforms-1.1.0