Bug 910603 - debug output printed to terminal upon engine-notifierd startup
debug output printed to terminal upon engine-notifierd startup
Status: CLOSED UPSTREAM
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine-notification-service (Show other bugs)
3.1.0
Unspecified Unspecified
unspecified Severity low
: ---
: 3.3.0
Assigned To: Martin Perina
Ilanit Stein
infra
:
: 885444 (view as bug list)
Depends On: 885446
Blocks: 915537 1019461
  Show dependency treegraph
 
Reported: 2013-02-12 18:22 EST by Greg Padgett
Modified: 2016-02-10 14:20 EST (History)
8 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: 885446
Environment:
Last Closed: 2013-07-31 07:20:29 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: Infra
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)
notifier.log from oVirt 3.3 (13.07 KB, text/x-log)
2013-07-31 07:19 EDT, Martin Perina
no flags Details

  None (edit)
Description Greg Padgett 2013-02-12 18:22:47 EST
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 07:02:24 EST
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 08:36:32 EST
*** Bug 885444 has been marked as a duplicate of this bug. ***
Comment 3 Martin Perina 2013-07-31 07:19:26 EDT
Created attachment 781043 [details]
notifier.log from oVirt 3.3

Unable to reproduce it on lastest oVirt 3.3

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