Bug 1051492 - [notifier] When a mail is resent after a SMTP issue, there's no info about it in logs
Summary: [notifier] When a mail is resent after a SMTP issue, there's no info about it...
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine-notification-service
Version: 3.4.0
Hardware: Unspecified
OS: Unspecified
unspecified
low
Target Milestone: ---
: 3.4.0
Assignee: Mooli Tayer
QA Contact: Jiri Belka
URL:
Whiteboard: infra
Depends On: 1071536
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-01-10 12:33 UTC by Jiri Belka
Modified: 2016-02-10 19:40 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:
oVirt Team: Infra
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
notifier.log (370.32 KB, application/x-gzip)
2014-01-10 12:36 UTC, Jiri Belka
no flags Details


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 24472 0 None None None Never
oVirt gerrit 24706 0 None None None Never

Description Jiri Belka 2014-01-10 12:33:48 UTC
Description of problem:
Not sure if current situation is the best. When SMTP does not work (iptables -I OUTPUT -d $smtp_server -j REJECT) the mail is obviously staying somewhere in queue, and after SMTP is available again (remote iptables rules), there's no line about resending.

2014-01-10 13:25:47,576 DEBUG [org.ovirt.engine.core.notifier.utils.sender.mail.EventSenderMailImpl] Send email to [jbelka]
 subject:
 [Alert Notification. (testovic.rhev.lab.eng.brq.redhat.com), [Host dell-r210ii-13 was switched to Maintenance mode by admin@internal.]]
 body:
 [Time:2014-01-10 13:25:45.67
Message:Host dell-r210ii-13 was switched to Maintenance mode by admin@internal.
Severity:0
User Name: admin@internal
Host Name: dell-r210ii-13
]
2014-01-10 13:25:48,723 ERROR [org.ovirt.engine.core.notifier.utils.sender.mail.JavaMailSender] Failed to send message  to jbelka with subject Alert Notification. 
(testovic.rhev.lab.eng.brq.redhat.com), [Host dell-r210ii-13 was switched to Maintenance mode by admin@internal.] due to to error: Could not connect to SMTP host: smtp.corp.r
edhat.com, port: 25
javax.mail.MessagingException: Could not connect to SMTP host: smtp.corp.redhat.com, port: 25;
  nested exception is:
        java.net.ConnectException: Connection refused
        at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:1972)
        at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:642)
        at javax.mail.Service.connect(Service.java:295)
        at javax.mail.Service.connect(Service.java:176)
        at javax.mail.Service.connect(Service.java:125)
        at javax.mail.Transport.send0(Transport.java:194)
        at javax.mail.Transport.send(Transport.java:124)
        at org.ovirt.engine.core.notifier.utils.sender.mail.JavaMailSender.send(JavaMailSender.java:152)
        at org.ovirt.engine.core.notifier.utils.sender.mail.EventSenderMailImpl.send(EventSenderMailImpl.java:79)
        at org.ovirt.engine.core.notifier.NotificationService.processEvents(NotificationService.java:263)
        at org.ovirt.engine.core.notifier.NotificationService.run(NotificationService.java:120)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:744)
Caused by: java.net.ConnectException: Connection refused
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.net.Socket.connect(Socket.java:579)
        at java.net.Socket.connect(Socket.java:528)
        at com.sun.mail.util.SocketFetcher.createSocket(SocketFetcher.java:319)
        at com.sun.mail.util.SocketFetcher.getSocket(SocketFetcher.java:233)
        at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:1938)
        ... 17 more

Version-Release number of selected component (if applicable):
is31 / rhevm-tools-3.3.0-0.44.el6ev.noarch

How reproducible:
100%

Steps to Reproduce:
1. block access to SMTP server
2. generate event
3. unblock access to SMTP server

Actual results:
error and then no info about resending

Expected results:
error, then a line about actual resending of message

Additional info:
Well I think it should be improved completely:

1. change from 'Send email' to 'Submitting for send'

2014-01-10 13:25:47,576 DEBUG [org.ovirt.engine.core.notifier.utils.sender.mail.EventSenderMailImpl] Send email to [jbelka]
 subject:
 [Alert Notification. (testovic.rhev.lab.eng.brq.redhat.com), [Host dell-r210ii-13 was switched to Maintenance mode by admin@internal.]]
 body:
 [Time:2014-01-10 13:25:45.67
Message:Host dell-r210ii-13 was switched to Maintenance mode by admin@internal.
Severity:0
User Name: admin@internal
Host Name: dell-r210ii-13
]

  as in this time it is not clear if actual sending would work.

2. if ERROR, then some msg about keeping the mail for later resend
3. if OK, then logged as successfully sent

Comment 1 Jiri Belka 2014-01-10 12:36:30 UTC
Created attachment 848157 [details]
notifier.log

Comment 2 Mooli Tayer 2014-02-14 00:11:03 UTC
We should change logging to log the event 
When we attempt to send it and not only before
The first attempt.

Comment 3 Jiri Belka 2014-03-21 09:10:53 UTC
ok, av3, tested with local stopped postfix which then was started.

Comment 4 Jiri Belka 2014-04-28 08:59:31 UTC
This works but in strange way in case of logging. From notifier.log it is not very understandable:

1. first discover of event

2014-04-28 10:34:59,673 INFO  [org.ovirt.engine.core.notifier.transport.smtp.Smtp] Send email to [jbelka]
 subject:
 [alertMessage (jb-rhevm34.rhev.lab.eng.brq.redhat.com), [user admin initiated console session for VM jb-w8-x86]]
2014-04-28 10:34:59,674 DEBUG [org.ovirt.engine.core.notifier.transport.smtp.Smtp] body:
 [<b>Time:</b> 2014-04-28 10:34:46.172<br><b>Message:</b> user admin initiated console session for VM jb-w8-x86<br><b>Severity:</b> NORMAL<p><b>User Name:</b> admin<br><b>VM Name:</b> jb-w8-x86<br><b>Host Name:</b> dell-r210ii-04<br><b>Template Name:</b> Blank<br><b>Data Center Name:</b> Default<br>]

2. probably another try to send

2014-04-28 10:36:22,791 INFO  [org.ovirt.engine.core.notifier.transport.smtp.Smtp] Send email to [jbelka]
 subject:
 [alertMessage (jb-rhevm34.rhev.lab.eng.brq.redhat.com), [user admin initiated console session for VM jb-w8-x86]]
2014-04-28 10:36:22,792 DEBUG [org.ovirt.engine.core.notifier.transport.smtp.Smtp] body:
 [<b>Time:</b> 2014-04-28 10:34:46.172<br><b>Message:</b> user admin initiated console session for VM jb-w8-x86<br><b>Severity:</b> NORMAL<p><b>User Name:</b> admin<br><b>VM Name:</b> jb-w8-x86<br><b>Host Name:</b> dell-r210ii-04<br><b>Template Name:</b> Blank<br><b>Data Center Name:</b> Default<br>]

3. timeout for sending mails

2014-04-28 10:37:25,795 ERROR [org.ovirt.engine.core.notifier.transport.smtp.Smtp] Failed to send message  to jbelka with subject alertMessage (jb-rhevm34.rhev.lab.eng.brq.redhat.com), [user admin initiated console session for VM jb-w8-x86] due to to error: Could not connect to SMTP host: 10.4.122.10, port: 587
javax.mail.MessagingException: Could not connect to SMTP host: 10.4.122.10, port: 587;
  nested exception is:
        java.net.ConnectException: Connection timed out

4. unblocked connection and another try

2014-04-28 10:37:45,799 INFO  [org.ovirt.engine.core.notifier.transport.smtp.Smtp] Send email to [jbelka]
 subject:
 [alertMessage (jb-rhevm34.rhev.lab.eng.brq.redhat.com), [user admin initiated console session for VM jb-w8-x86]]
2014-04-28 10:37:45,800 DEBUG [org.ovirt.engine.core.notifier.transport.smtp.Smtp] body:
 [<b>Time:</b> 2014-04-28 10:34:46.172<br><b>Message:</b> user admin initiated console session for VM jb-w8-x86<br><b>Severity:</b> NORMAL<p><b>User Name:</b> admin<br><b>VM Name:</b> jb-w8-x86<br><b>Host Name:</b> dell-r210ii-04<br><b>Template Name:</b> Blank<br><b>Data Center Name:</b> Default<br>]

so...

1. "Send email..."
2. "Send email..."
3. timeout
4. "Send email..."

Sorry but this is confusing. You inform in the log that something is 'send' (ok, this is not 'sent') but anyway. This is why I wronte in the description "1. change from 'Send email' to 'Submitting for send'".

So for me the flow for easy troubleshooting should be like this:

1a. "Queued email..."
1b. "Sending queued mails..."
2a. "Sending queued mails..."
3. timeout, sending of queue mails fails, will try again...
4. "Sending queued mails..."
5. "Queued mails sent...", mail queue now is empty

Thus putting it back to ASSIGNED as there was almost nothing done to change logging part to make it more understandable.

Comment 5 Mooli Tayer 2014-04-29 11:34:29 UTC
Hello Jiri,

Currently we do not log when adding to mail queue: 
"Queued email..." 

Or when the queue is empty:
"Queued mails sent...", mail queue now is empty

Or anything related to the queue. 
That can change if there is any benefit to users to know about it
(I'm not sure).

However it is unrelated to this bug named: "When a mail is resent after a SMTP issue, there's no info about it in logs" so I think it should be closed.

Currently we print the same message (same one from before this feature) 
each time an email is sent.

PS from my point of view what is mostly missing here is after
"Send email..."
to have
"Email sent successfully"
OR
"Sending email failed"

Comment 6 Mooli Tayer 2014-04-29 11:42:04 UTC
nit fix I see we do have a:
"Failed to send message" + explanation message in case of failure.

Comment 7 Jiri Belka 2014-04-30 08:35:56 UTC
ok av7. after discussion things got clarified: each mail notification gets separate 'Failed to send' error in the log, then each mail is sent.

Comment 8 Itamar Heim 2014-06-12 14:09:34 UTC
Closing as part of 3.4.0


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