Bug 910603

Summary: debug output printed to terminal upon engine-notifierd startup
Product: Red Hat Enterprise Virtualization Manager Reporter: Greg Padgett <gpadgett>
Component: ovirt-engine-notification-serviceAssignee: Martin Perina <mperina>
Status: CLOSED UPSTREAM QA Contact: Ilanit Stein <istein>
Severity: low Docs Contact:
Priority: unspecified    
Version: 3.1.0CC: acathrow, amureini, bazulay, iheim, istein, jkt, nslomian, Rhev-m-bugs, yzaslavs
Target Milestone: ---   
Target Release: 3.3.0   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: infra
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: 885446 Environment:
Last Closed: 2013-07-31 11:20:29 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Infra RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 885446    
Bug Blocks: 915537, 1019461    
Attachments:
Description Flags
notifier.log from oVirt 3.3 none

Description Greg Padgett 2013-02-12 23:22:47 UTC
Cloning to separate 2 issues in prior bug:
bug 885446 - "find" error printed to terminal upon notifier startup
 - root cause found, fix expected in 3.2.0
this bug - JavaMail debug output printed to terminal upon notifier startup
 - still in progress, may not make it in 3.2.0

+++ This bug was initially created as a clone of Bug #885446 +++

Description of problem:

When moving to DEBUG mode in /etc/ovirt-engine/notifier/log4j.xml,
After notifier service restart, linux error appear:
"find: failed to restore initial working directory: Permission denied"


Log:
===
> [root@lilach-rhel ~]# vi /etc/ovirt-engine/notifier/log4j.xml (set mode to DEBUG)


> [root@lilach-rhel ~]# /etc/rc.d/init.d/engine-notifierd restart

Printed on cli screen as response to the restart:

> Stopping engine-notifier:                                  [  OK  ]
> Starting engine-notifier: at Tue Dec  4 16:59:46 IST 2012find: failed to
> restore initial working directory: Permission denied find: failed to
> restore initial working directory: Permission denied find: failed to
> restore initial working directory: Permission denied find: failed to
> restore initial working directory: Permission denied find: failed to
> restore initial working directory: Permission denied [  OK  ]


> [root@lilach-rhel ~]# DEBUG: JavaMail version 1.4.4-redhat-1
> DEBUG: successfully loaded resource: /META-INF/javamail.default.providers
> DEBUG: Tables of loaded providers
> DEBUG: Providers Listed By Class Name:
> {com.sun.mail.smtp.SMTPSSLTransport=javax.mail.Provider[TRANSPORT,smtps,com
> .sun.mail.smtp.SMTPSSLTransport,Sun Microsystems, Inc],
> com.sun.mail.smtp.SMTPTransport=javax.mail.Provider[TRANSPORT,smtp,com.sun.
> mail.smtp.SMTPTransport,Sun Microsystems, Inc],
> com.sun.mail.imap.IMAPSSLStore=javax.mail.Provider[STORE,imaps,com.sun.mail
> .imap.IMAPSSLStore,Sun Microsystems, Inc],
> com.sun.mail.pop3.POP3SSLStore=javax.mail.Provider[STORE,pop3s,com.sun.mail
> .pop3.POP3SSLStore,Sun Microsystems, Inc],
> com.sun.mail.imap.IMAPStore=javax.mail.Provider[STORE,imap,com.sun.mail.ima
> p.IMAPStore,Sun Microsystems, Inc],
> com.sun.mail.pop3.POP3Store=javax.mail.Provider[STORE,pop3,com.sun.mail.pop
> 3.POP3Store,Sun Microsystems, Inc]} DEBUG: Providers Listed By Protocol:
> {imaps=javax.mail.Provider[STORE,imaps,com.sun.mail.imap.IMAPSSLStore,Sun
> Microsystems, Inc],
> imap=javax.mail.Provider[STORE,imap,com.sun.mail.imap.IMAPStore,Sun
> Microsystems, Inc],
> smtps=javax.mail.Provider[TRANSPORT,smtps,com.sun.mail.smtp.SMTPSSLTranspor
> t,Sun Microsystems, Inc],
> pop3=javax.mail.Provider[STORE,pop3,com.sun.mail.pop3.POP3Store,Sun
> Microsystems, Inc],
> pop3s=javax.mail.Provider[STORE,pop3s,com.sun.mail.pop3.POP3SSLStore,Sun
> Microsystems, Inc],
> smtp=javax.mail.Provider[TRANSPORT,smtp,com.sun.mail.smtp.SMTPTransport,Sun
> Microsystems, Inc]} DEBUG: successfully loaded resource:
> /META-INF/javamail.default.address.map

--- Additional comment from Yair Zaslavsky on 2012-12-30 06:25:07 EST ---

Are you sure this relates to setting to debug? what happens when you set back to info?

--- Additional comment from Ilanit Stein on 2012-12-31 07:26:27 EST ---

The linux error "find: failed to restore initial working directory: Permission denied" appear for all priority levels (DEBUG, INFO, ERROR).
for DEBUG level,

Messages "DEBUG: JavaMail version 1.4.4-redhat-1
> DEBUG: successfully loaded resource: /META-INF/javamail.default.providers ..."
from the above bug description appear only for DEBUG priority level.

Bug subject has been changed accordingly.

--- Additional comment from Barak on 2013-01-02 09:22:19 EST ---

Is it a file permissions issue ?
What are the permissions of: 

/etc/ovirt-engine/notifier
/etc/ovirt-engine/notifier/log4j.xml
/etc/ovirt-engine/notifier/notifier.conf

--- Additional comment from Ilanit Stein on 2013-01-16 04:38:35 EST ---

drwxr-xr-x. 2 root  root  4096 Jan  8 15:43 notifier
-rw-r-----. 1 ovirt ovirt 3106 Dec 26 15:59 notifier.conf
-rw-r--r--. 1 root  root  1320 Dec 26 15:59 log4j.xml

--- Additional comment from Greg Padgett on 2013-02-06 12:59:02 EST ---

(In reply to comment #2)
> The linux error "find: failed to restore initial working directory:
> Permission denied" appear for all priority levels (DEBUG, INFO, ERROR).
> for DEBUG level,

I was able to reproduce this; it's due to the init script executing `find` as user ovirt from root's home directory.  I've submitted a simple fix to upstream, linked in the ovirt gerrit tracker.

> Messages "DEBUG: JavaMail version 1.4.4-redhat-1
> > DEBUG: successfully loaded resource: /META-INF/javamail.default.providers ..."
> from the above bug description appear only for DEBUG priority level.

Can you attach your /etc/ovirt-engine/notifier/log4j.xml file?

--- Additional comment from Ilanit Stein on 2013-02-07 01:21:32 EST ---

/etc/ovirt-engine/notifier/log4j.xml 
(priority set by priority value="INFO","DEBUG", "ERROR"):
====================================================================
<?xml version="1.0" encoding="UTF-8"?><!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">

    <!-- Log levels:DEBUG,INFO,WARN,ERROR,FATAL -->
    <appender name="FILE" class="org.apache.log4j.RollingFileAppender">
        <param name="File" value="/var/log/ovirt-engine/notifier/notifier.log" />
        <param name="Append" value="true" />
        <param name="MaxFileSize" value="10000KB" />
        <param name="MaxBackupIndex" value="5" />

        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d %-5p [%c] %m%n" />
            <!--  <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n" /> -->

        </layout>
    </appender>

    <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out" />
        <layout class="org.apache.log4j.PatternLayout">
            <!-- The default pattern: Date Priority [Category] Message\n -->
            <param name="ConversionPattern" value="%d %-5p [%c] (%t) %m%n" />
        </layout>
    </appender>

    <root>
        <priority value="INFO" />
        <!-- appender-ref ref="CONSOLE" /-->
        <appender-ref ref="FILE" />
    </root>

</log4j:configuration>

Comment 1 Ilanit Stein 2013-02-28 12:02:24 UTC
Problem reproduced on sf-8:

[root@istein-32 ~]# DEBUG: JavaMail version 1.4.4-redhat-2
DEBUG: successfully loaded resource: /META-INF/javamail.default.providers
DEBUG: Tables of loaded providers
DEBUG: Providers Listed By Class Name: {com.sun.mail.smtp.SMTPSSLTransport=javax.mail.Provider[TRANSPORT,smtps,com.sun.mail.smtp.SMTPSSLTransport,Sun Microsystems, Inc], com.sun.mail.smtp.SMTPTransport=javax.mail.Provider[TRANSPORT,smtp,com.sun.mail.smtp.SMTPTransport,Sun Microsystems, Inc], com.sun.mail.imap.IMAPSSLStore=javax.mail.Provider[STORE,imaps,com.sun.mail.imap.IMAPSSLStore,Sun Microsystems, Inc], com.sun.mail.pop3.POP3SSLStore=javax.mail.Provider[STORE,pop3s,com.sun.mail.pop3.POP3SSLStore,Sun Microsystems, Inc], com.sun.mail.imap.IMAPStore=javax.mail.Provider[STORE,imap,com.sun.mail.imap.IMAPStore,Sun Microsystems, Inc], com.sun.mail.pop3.POP3Store=javax.mail.Provider[STORE,pop3,com.sun.mail.pop3.POP3Store,Sun Microsystems, Inc]}
DEBUG: Providers Listed By Protocol: {imaps=javax.mail.Provider[STORE,imaps,com.sun.mail.imap.IMAPSSLStore,Sun Microsystems, Inc], imap=javax.mail.Provider[STORE,imap,com.sun.mail.imap.IMAPStore,Sun Microsystems, Inc], smtps=javax.mail.Provider[TRANSPORT,smtps,com.sun.mail.smtp.SMTPSSLTransport,Sun Microsystems, Inc], pop3=javax.mail.Provider[STORE,pop3,com.sun.mail.pop3.POP3Store,Sun Microsystems, Inc], pop3s=javax.mail.Provider[STORE,pop3s,com.sun.mail.pop3.POP3SSLStore,Sun Microsystems, Inc], smtp=javax.mail.Provider[TRANSPORT,smtp,com.sun.mail.smtp.SMTPTransport,Sun Microsystems, Inc]}
DEBUG: successfully loaded resource: /META-INF/javamail.default.address.map

/etc/ovirt-engine/notifier/log4j.xml:
------------------------------------

<?xml version="1.0" encoding="UTF-8"?><!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/" debug="false">

    <!-- Log levels:DEBUG,INFO,WARN,ERROR,FATAL -->
    <appender name="FILE" class="org.apache.log4j.RollingFileAppender">
        <param name="File" value="/var/log/ovirt-engine/notifier/notifier.log" />
        <param name="Append" value="true" />
        <param name="MaxFileSize" value="10000KB" />
        <param name="MaxBackupIndex" value="5" />

        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d %-5p [%c] %m%n" />
            <!--  <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n" /> -->

        </layout>
    </appender>

    <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out" />
        <layout class="org.apache.log4j.PatternLayout">
            <!-- The default pattern: Date Priority [Category] Message\n -->
            <param name="ConversionPattern" value="%d %-5p [%c] (%t) %m%n" />
        </layout>
    </appender>

    <root>
        <priority value="ERROR" />
        <!-- appender-ref ref="CONSOLE" /-->
        <appender-ref ref="FILE" />
    </root>

    <logger name="org.ovirt.engine.core">
        <level value="DEBUG"/>
    </logger>

</log4j:configuration>

/etc/ovirt-engine/notifier/notifier.conf:
----------------------------------------
#
# This file holds the configuration of oVirt events notification daemon.
# The daemon consists of two major services: notification service and engine monitoring.
#

#-------------------------------------#
# Notification Service Configuration: #
#-------------------------------------#
# Interval (in seconds) between iterations of dispatching messages to subscribers. Default is 120 seconds.
INTERVAL_IN_SECONDS=2

# The SMTP mail server address. Required.
MAIL_SERVER=localhost

# The default port of non-secured SMTP server is 25, for secured (ssl enabled) 465.
#MAIL_PORT=25

# Required if SSL enabled to authenticate the user. Used also to specify 'from' user address if mail server
# supports, when MAIL_FROM is not set. Address is in RFC822 format
#MAIL_USER=

# Required to authenticate the user if mail server requires authentication or if SSL is enabled
#MAIL_PASSWORD=

# Indicates whether SSL should be used to communicate with mail server. Default is false.
#MAIL_ENABLE_SSL=true

# If set to true, sends a message in HTML format. Default is false.
#HTML_MESSAGE_FORMAT=true

# Specifies 'from' address on sent mail in RFC822 format, if supported by mail server.
#MAIL_FROM=

# Specifies 'reply-to' address on sent mail in RFC822 format.
#MAIL_REPLY_TO=

# Amount of days to keep dispatched events on history table. If not set, events remain on history table.
#DAYS_TO_KEEP_HISTORY=30

# This parameter specifies how many days of old events are processed and sent
# when the notifier starts. If set to 2, for example, the notifier will
# process and send the events of the last two days, older events will just
# be marked as processed and won't be sent. The default is 0, so no old
# messages will be sent at all during startup.
#DAYS_TO_SEND_ON_STARTUP=0

#----------------------------------#
# Engine Monitoring Configuration: #
#----------------------------------#
# Interval (in seconds) between engine server monitoring iterations. Interval is being measured from
# the time an iteration is completed. Default is 300 seconds.
ENGINE_INTERVAL_IN_SECONDS=3

# Number of retries to monitor server status per iteration. Default is 3 retries.
ENGINE_MONITOR_RETRIES=3

# Time (in seconds) to wait between retries. Default is 30 seconds.
ENGINE_TIMEOUT_IN_SECONDS=3

# If running Jboss in secure mode, should be set to true. Default is false.
#IS_HTTPS_PROTOCOL=true

# Specifies the protocol used by Jboss Configuration Connector when SSL is enabled. Default is 'TLS'.
#SSL_PROTOCOL=TLS

# If running Jboss in secure mode, and wishes to ignore SSL errors, should set to true. Default is false.
#SSL_IGNORE_CERTIFICATE_ERRORS=false

# If running Jboss in secure mode, and wishes to ignore hostname verification, should set to true. Default is false.
# If setting this property to 'true', SSL_IGNORE_CERTIFICATE_ERRORS considered to be set to 'true' as well: disabling host name
# verification means that it will not be verified against the certification, therefore certification errors are ignored.
#SSL_IGNORE_HOST_VERIFICATION=false

# Specifies whether to repeat auditing of failure messages of non-responding engine server. Default is false (meaning
# repeated failure messages will NOT be sent to the subscribers)
#REPEAT_NON_RESPONSIVE_NOTIFICATION=false

Comment 2 Yair Zaslavsky 2013-03-05 13:36:32 UTC
*** Bug 885444 has been marked as a duplicate of this bug. ***

Comment 3 Martin Perina 2013-07-31 11:19:26 UTC
Created attachment 781043 [details]
notifier.log from oVirt 3.3

Unable to reproduce it on lastest oVirt 3.3