Bug 1009149

Summary: don't log messages to console when starting - use log file
Product: [Other] RHQ Project Reporter: John Mazzitelli <mazz>
Component: Launch ScriptsAssignee: Nobody <nobody>
Status: NEW --- QA Contact:
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 4.9CC: hrupp, jshaughn
Target Milestone: ---   
Target Release: RHQ 4.13   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description John Mazzitelli 2013-09-17 19:22:05 UTC
When starting via rhqctl start, the server and agent start quietly (no log messages dumped to console) but the storage node dumps log messages to the console, making it noisy.

We should make the console output quiet - log the messages to the log file. This way, when starting successfullly, we should just see some simple and short success type messages (e.g. "Starting server" or "Starting storage" or "starting agent" - thigns like that).

Comment 1 John Mazzitelli 2013-09-17 19:24:13 UTC
For example, look at the noisiness of this, for just successfully starting via rhqctl start:

================

$ ./rhqctl start
15:18:53,588 INFO  [org.jboss.modules] JBoss Modules version 1.2.0.CR1
 INFO 15:18:54,454 Logging initialized
 INFO 15:18:54,477 JVM vendor/version: Java HotSpot(TM) 64-Bit Server VM/1.7.0_11
 INFO 15:18:54,478 Heap size: 523501568/523501568
 INFO 15:18:54,478 Classpath: ./../conf:./../build/classes/main:./../build/classes/thrift:./../lib/antlr-3.2.jar:./../lib/apache-cassandra-1.2.9.jar:./../lib/apache-cassandra-clientutil-1.2.9.jar:./../lib/apache-cassandra-thrift-1.2.9.jar:./../lib/avro-1.4.0-fixes.jar:./../lib/avro-1.4.0-sources-fixes.jar:./../lib/commons-cli-1.1.jar:./../lib/commons-codec-1.2.jar:./../lib/commons-lang-2.6.jar:./../lib/compress-lzf-0.8.4.jar:./../lib/concurrentlinkedhashmap-lru-1.3.jar:./../lib/guava-13.0.1.jar:./../lib/high-scale-lib-1.1.2.jar:./../lib/jackson-core-asl-1.9.2.jar:./../lib/jackson-mapper-asl-1.9.2.jar:./../lib/jamm-0.2.5.jar:./../lib/jbcrypt-0.3m.jar:./../lib/jline-1.0.jar:./../lib/json-simple-1.1.jar:./../lib/libthrift-0.7.0.jar:./../lib/log4j-1.2.16.jar:./../lib/metrics-core-2.0.3.jar:./../lib/netty-3.6.6.Final.jar:./../lib/rhq-cassandra-auth-4.9.0.jar:./../lib/servlet-api-2.5-20081211.jar:./../lib/slf4j-api-1.7.2.jar:./../lib/slf4j-log4j12-1.7.2.jar:./../lib/snakeyaml-1.6.jar:./../lib/snappy-java-1.0.4.1-rhq-p1.jar:./../lib/snaptree-0.1.jar:./../lib/jamm-0.2.5.jar
 INFO 15:18:54,480 JNA not found. Native methods will be disabled.
 INFO 15:18:54,496 Loading settings from file:/home/mazz/Downloads/rhq-server-4.9.0/rhq-storage/conf/cassandra.yaml
 INFO 15:18:54,972 Data files directories: [/tmp/storage/data]
 INFO 15:18:54,973 Commit log directory: /tmp/storage/commitlog
 INFO 15:18:54,973 DiskAccessMode 'auto' determined to be mmap, indexAccessMode is mmap
 INFO 15:18:54,973 disk_failure_policy is stop
 INFO 15:18:54,995 Global memtable threshold is enabled at 166MB
 INFO 15:18:55,200 Not using multi-threaded compaction
 WARN 15:18:55,238 Cannot initialize native Snappy library. Compression on new tables will be disabled.
 INFO 15:18:55,501 Initializing key cache with capacity of 24 MBs.
 INFO 15:18:55,512 Scheduling key cache save to each 14400 seconds (going to save all keys).
Trying to start the RHQ Server...
RHQ Server                     (pid 14555  ) IS starting
Starting RHQ Agent...
RHQ Agent (pid 14758 ) IS running

============

It should be something like this:

==============

$ ./rhqctl start
15:18:53,588 INFO  [org.jboss.modules] JBoss Modules version 1.2.0.CR1
Trying to start the RHQ Storage Node...
RHQ Storage Node               (pid 12345  ) IS starting
Trying to start the RHQ Server...
RHQ Server                     (pid 14555  ) IS starting
Starting RHQ Agent...
RHQ Agent (pid 14758 ) IS running

Comment 2 John Mazzitelli 2013-09-18 12:13:22 UTC
(05:10:51 PM) mazz: RHQ storage node (pid=32216) is stopping...
(05:10:51 PM) mazz: kill 32216: No such process
(05:10:51 PM) mazz: RHQ storage node has stopped
(05:10:57 PM) mazz: that worries me - my stuff was running
(05:11:10 PM) mazz: curious to know why its saying it can't find the process
(03:58:17 AM) pilhuhn: mazz that is trying to run a kill on the pid in the pid file to see if the process is really gone. rhqctl has to wait until this is dead, otherwise re-starts will end up dead in the water, as the old storage process is not yet dead

This is another instance where we should not output things to the console - can we redirect the kill output to /dev/null? This message was confusing to me - it looks like some error was happening - like it tried to shutdown the storage node, but it couldnt' because the pid wasn't found. But then it says it "stopped" - I wasn't sure if it really did stop or if the kill message meant some unexpected error happened.

Comment 3 Heiko W. Rupp 2014-05-08 14:42:57 UTC
Bump the target version now that 4.11 is out.