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
Created attachment 848157 [details] notifier.log
We should change logging to log the event When we attempt to send it and not only before The first attempt.
ok, av3, tested with local stopped postfix which then was started.
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.
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"
nit fix I see we do have a: "Failed to send message" + explanation message in case of failure.
ok av7. after discussion things got clarified: each mail notification gets separate 'Failed to send' error in the log, then each mail is sent.
Closing as part of 3.4.0