Some emails are not sent

Use this forum if you have installed hMailServer and want to ask a question related to a production release of hMailServer. Before posting, please read the troubleshooting guide. A large part of all reported issues are already described in detail here.
Post Reply
byebyebyte
New user
New user
Posts: 4
Joined: 2014-06-10 07:14

Some emails are not sent

Post by byebyebyte » 2014-06-10 07:33

Hi,

I am using hMailServer as an SMTP relay to allow devices (UPS, HP iLO, NAS, etc.) that don't support SMTP AUTH or SSL/TLS to send mail externally. I used this guide to set up hMailServer:
https://ceics.com/support/google-mail-s ... y-solution

During my tests I noticed that some test emails don't get sent. I have one such incident from the log below. Notice the first attempt at 14:13 which seems to have hung and the second attempt at 14:17 which was successful.

I can't replicate this as I have made dozens of tests before and after which were all successful. I'm just wondering if this is an issue on the SMTP client (HP iLO in this case) or hMailServer?

Thanks in advance.

Code: Select all

"TCPIP"	10956	"2014-06-10 14:13:39.846"	"TCP - 10.0.0.2 connected to 10.0.0.4:25."
"SMTPD"	10956	323	"2014-06-10 14:13:39.850"	"10.0.0.2"	"SENT: 220 10.0.0.4 ESMTP"
"SMTPD"	10956	323	"2014-06-10 14:13:39.852"	"10.0.0.2"	"RECEIVED: HELO [10.0.0.2]"
"SMTPD"	10956	323	"2014-06-10 14:13:39.853"	"10.0.0.2"	"SENT: 250 Hello."
"SMTPD"	8776	323	"2014-06-10 14:13:39.854"	"10.0.0.2"	"RECEIVED: MAIL FROM: iLO.domain.local@domain.local"
"SMTPD"	8776	323	"2014-06-10 14:13:39.862"	"10.0.0.2"	"SENT: 250 OK"
"SMTPD"	10956	323	"2014-06-10 14:13:39.863"	"10.0.0.2"	"RECEIVED: RCPT TO: notifications@external-domain.com"
"SMTPD"	10956	323	"2014-06-10 14:13:39.868"	"10.0.0.2"	"SENT: 250 OK"
"SMTPD"	8776	323	"2014-06-10 14:13:39.869"	"10.0.0.2"	"RECEIVED: DATA"
"SMTPD"	8776	323	"2014-06-10 14:13:39.870"	"10.0.0.2"	"SENT: 354 OK, send."
"TCPIP"	10956	"2014-06-10 14:17:35.304"	"TCP - 10.0.0.2 connected to 10.0.0.4:25."
"SMTPD"	10956	324	"2014-06-10 14:17:35.308"	"10.0.0.2"	"SENT: 220 10.0.0.4 ESMTP"
"SMTPD"	10956	324	"2014-06-10 14:17:35.310"	"10.0.0.2"	"RECEIVED: HELO [10.0.0.2]"
"SMTPD"	10956	324	"2014-06-10 14:17:35.311"	"10.0.0.2"	"SENT: 250 Hello."
"SMTPD"	8776	324	"2014-06-10 14:17:35.314"	"10.0.0.2"	"RECEIVED: MAIL FROM: iLO.domain.local@domain.local"
"SMTPD"	8776	324	"2014-06-10 14:17:35.320"	"10.0.0.2"	"SENT: 250 OK"
"SMTPD"	8776	324	"2014-06-10 14:17:35.377"	"10.0.0.2"	"RECEIVED: RCPT TO: notifications@external-domain.com"
"SMTPD"	8776	324	"2014-06-10 14:17:35.382"	"10.0.0.2"	"SENT: 250 OK"
"SMTPD"	8776	324	"2014-06-10 14:17:35.384"	"10.0.0.2"	"RECEIVED: DATA"
"SMTPD"	8776	324	"2014-06-10 14:17:35.385"	"10.0.0.2"	"SENT: 354 OK, send."
"SMTPD"	8788	324	"2014-06-10 14:17:36.303"	"10.0.0.2"	"SENT: 250 Queued (0.906 seconds)"
"SMTPD"	2636	324	"2014-06-10 14:17:36.305"	"10.0.0.2"	"RECEIVED: QUIT"
"SMTPD"	2636	324	"2014-06-10 14:17:36.306"	"10.0.0.2"	"SENT: 221 goodbye"
"APPLICATION"	1384	"2014-06-10 14:17:36.310"	"SMTPDeliverer - Message 284: Delivering message from iLO.domain.local@domain.local to notifications@external-domain.com. File: C:\Program Files (x86)\hMailServer\Data\{A3DB75A2-E723-4F7C-8AC8-F66649958BB9}.eml"
"APPLICATION"	1384	"2014-06-10 14:17:36.314"	"SMTPDeliverer - Message 284: Relaying to host smtp.gmail.com."
"TCPIP"	1384	"2014-06-10 14:17:36.316"	"Connecting to smtp.gmail.com..."
"SMTPC"	14116	325	"2014-06-10 14:17:37.022"	"173.194.79.109"	"RECEIVED: 220 mx.google.com ESMTP zc10sm6365626pac.46 - gsmtp"
"SMTPC"	14116	325	"2014-06-10 14:17:37.023"	"173.194.79.109"	"SENT: EHLO 10.0.0.4"
"SMTPC"	1224	325	"2014-06-10 14:17:37.226"	"173.194.79.109"	"RECEIVED: 250-mx.google.com at your service, [165.228.202.193]"
"SMTPC"	12912	325	"2014-06-10 14:17:37.227"	"173.194.79.109"	"RECEIVED: 250-SIZE 35882577"
"SMTPC"	1224	325	"2014-06-10 14:17:37.227"	"173.194.79.109"	"RECEIVED: 250-8BITMIME"
"SMTPC"	11536	325	"2014-06-10 14:17:37.227"	"173.194.79.109"	"RECEIVED: 250-AUTH LOGIN PLAIN XOAUTH XOAUTH2 PLAIN-CLIENTTOKEN"
"SMTPC"	14116	325	"2014-06-10 14:17:37.228"	"173.194.79.109"	"RECEIVED: 250-ENHANCEDSTATUdomainODES"
"SMTPC"	11536	325	"2014-06-10 14:17:37.228"	"173.194.79.109"	"RECEIVED: 250 CHUNKING"
"SMTPC"	11536	325	"2014-06-10 14:17:37.228"	"173.194.79.109"	"SENT: AUTH LOGIN"
"SMTPC"	10832	325	"2014-06-10 14:17:37.515"	"173.194.79.109"	"RECEIVED: 334 VXNlcm5hbWU6"
"SMTPC"	10832	325	"2014-06-10 14:17:37.515"	"173.194.79.109"	"SENT: c21vcmdvbi5ub3RpZnlAZ21haWwuY29t"
"SMTPC"	13308	325	"2014-06-10 14:17:37.717"	"173.194.79.109"	"RECEIVED: 334 UGFzc3dvcmQ6"
"SMTPC"	13308	325	"2014-06-10 14:17:37.718"	"173.194.79.109"	"SENT: ***"
"SMTPC"	10956	325	"2014-06-10 14:17:38.110"	"173.194.79.109"	"RECEIVED: 235 2.7.0 Accepted"
"SMTPC"	10956	325	"2014-06-10 14:17:38.111"	"173.194.79.109"	"SENT: MAIL FROM:<iLO.domain.local@domain.local>"
"SMTPC"	11256	325	"2014-06-10 14:17:38.516"	"173.194.79.109"	"RECEIVED: 250 2.1.0 OK zc10sm6365626pac.46 - gsmtp"
"SMTPC"	11256	325	"2014-06-10 14:17:38.516"	"173.194.79.109"	"SENT: RCPT TO:<notifications@external-domain.com>"
"SMTPC"	4828	325	"2014-06-10 14:17:38.721"	"173.194.79.109"	"RECEIVED: 250 2.1.5 OK zc10sm6365626pac.46 - gsmtp"
"SMTPC"	4828	325	"2014-06-10 14:17:38.721"	"173.194.79.109"	"SENT: DATA"
"SMTPC"	2636	325	"2014-06-10 14:17:39.167"	"173.194.79.109"	"RECEIVED: 354  Go ahead zc10sm6365626pac.46 - gsmtp"
"SMTPC"	2636	325	"2014-06-10 14:17:39.169"	"173.194.79.109"	"SENT: [nl]."
"SMTPC"	10408	325	"2014-06-10 14:17:40.202"	"173.194.79.109"	"RECEIVED: 250 2.0.0 OK 1402373860 zc10sm6365626pac.46 - gsmtp"
"SMTPC"	10408	325	"2014-06-10 14:17:40.203"	"173.194.79.109"	"SENT: QUIT"
"SMTPC"	5452	325	"2014-06-10 14:17:40.518"	"173.194.79.109"	"RECEIVED: 221 2.0.0 closing connection zc10sm6365626pac.46 - gsmtp"
"APPLICATION"	1384	"2014-06-10 14:17:40.525"	"SMTPDeliverer - Message 284: Message delivery thread completed."

Bill48105
Developer
Developer
Posts: 6192
Joined: 2010-04-24 23:16
Location: Michigan, USA

Re: Some emails are not sent

Post by Bill48105 » 2014-06-10 08:55

I don't see any problems in your logs. The 1st part is SMTPD where email arrives & 2nd part is SMTPC where email is being relayed out to google. Both result in successful transmission with no error. Did you share the correct log snippet?
Thx
Bill
hMailServer build LIVE on my servers: 5.4-B2014050402
#hmailserver on FreeNode IRC https://webchat.freenode.net/?channels=#hmailserver
*** ABSENT FROM hMail! Those in IRC know how to find me if urgent. ***

byebyebyte
New user
New user
Posts: 4
Joined: 2014-06-10 07:14

Re: Some emails are not sent

Post by byebyebyte » 2014-06-10 09:25

Thank you. Yes I am certain of it. Here's another example from today. Notice how the first attempt hangs at the same point:
"SENT: 354 OK, send."
To be clear, each of the two snippets I quoted show two incidents of test mail being sent from iLO. This is what actually happened:
Hitting Test Mail on iLo at 12:41 - fail
Hitting Test Mail on iLo at 12:43 - success
Hitting Test Mail on iLo at 14:13 - fail
Hitting Test Mail on iLo at 14:17 - success
("fail" = mail wasn't relayed by hMailServer, hung on "SENT: 354 OK, send". Nothing received by mail client)
("success" = mail was relayed and received by mail client)

Code: Select all

"SMTPD"	10956	298	"2014-06-10 12:41:33.455"	"10.0.0.2"	"SENT: 220 10.0.0.4 ESMTP"
"SMTPD"	10956	298	"2014-06-10 12:41:33.457"	"10.0.0.2"	"RECEIVED: HELO [10.0.0.2]"
"SMTPD"	10956	298	"2014-06-10 12:41:33.458"	"10.0.0.2"	"SENT: 250 Hello."
"SMTPD"	10956	298	"2014-06-10 12:41:33.476"	"10.0.0.2"	"RECEIVED: MAIL FROM: iLO.domain.local@external-domain.com"
"SMTPD"	10956	298	"2014-06-10 12:41:33.481"	"10.0.0.2"	"SENT: 250 OK"
"SMTPD"	10408	298	"2014-06-10 12:41:33.485"	"10.0.0.2"	"RECEIVED: RCPT TO: notifications@external-domain.com"
"SMTPD"	10408	298	"2014-06-10 12:41:33.503"	"10.0.0.2"	"SENT: 250 OK"
"SMTPD"	10408	298	"2014-06-10 12:41:33.504"	"10.0.0.2"	"RECEIVED: DATA"
"SMTPD"	10408	298	"2014-06-10 12:41:33.505"	"10.0.0.2"	"SENT: 354 OK, send."
"TCPIP"	10956	"2014-06-10 12:43:36.063"	"TCP - 10.0.0.2 connected to 10.0.0.4:25."
"SMTPD"	10956	299	"2014-06-10 12:43:36.068"	"10.0.0.2"	"SENT: 220 10.0.0.4 ESMTP"
"SMTPD"	10956	299	"2014-06-10 12:43:36.070"	"10.0.0.2"	"RECEIVED: HELO [10.0.0.2]"
"SMTPD"	10956	299	"2014-06-10 12:43:36.071"	"10.0.0.2"	"SENT: 250 Hello."
"SMTPD"	12912	299	"2014-06-10 12:43:36.072"	"10.0.0.2"	"RECEIVED: MAIL FROM: iLO.domain.local@domain.local"
"SMTPD"	12912	299	"2014-06-10 12:43:36.079"	"10.0.0.2"	"SENT: 250 OK"
"SMTPD"	11536	299	"2014-06-10 12:43:36.132"	"10.0.0.2"	"RECEIVED: RCPT TO: notifications@external-domain.com"
"SMTPD"	11536	299	"2014-06-10 12:43:36.137"	"10.0.0.2"	"SENT: 250 OK"
"SMTPD"	10956	299	"2014-06-10 12:43:36.139"	"10.0.0.2"	"RECEIVED: DATA"
"SMTPD"	10956	299	"2014-06-10 12:43:36.140"	"10.0.0.2"	"SENT: 354 OK, send."
"SMTPD"	8788	299	"2014-06-10 12:43:37.058"	"10.0.0.2"	"SENT: 250 Queued (0.922 seconds)"
"SMTPD"	10956	299	"2014-06-10 12:43:37.082"	"10.0.0.2"	"RECEIVED: QUIT"
"SMTPD"	10956	299	"2014-06-10 12:43:37.082"	"10.0.0.2"	"SENT: 221 goodbye"
"APPLICATION"	1384	"2014-06-10 12:43:37.084"	"SMTPDeliverer - Message 274: Delivering message from iLO.domain.local@domain.local to notifications@external-domain.com. File: C:\Program Files (x86)\hMailServer\Data\{FD7BDD7C-406E-4A92-897A-68D3E43FC847}.eml"
"APPLICATION"	1384	"2014-06-10 12:43:37.088"	"SMTPDeliverer - Message 274: Relaying to host smtp.gmail.com."
"TCPIP"	1384	"2014-06-10 12:43:37.090"	"Connecting to smtp.gmail.com..."
"SMTPC"	11256	300	"2014-06-10 12:43:37.799"	"74.125.129.109"	"RECEIVED: 220 mx.google.com ESMTP ia2sm66498447pbb.32 - gsmtp"
"SMTPC"	11256	300	"2014-06-10 12:43:37.800"	"74.125.129.109"	"SENT: EHLO 10.0.0.4"
"SMTPC"	12912	300	"2014-06-10 12:43:38.003"	"74.125.129.109"	"RECEIVED: 250-mx.google.com at your service, [165.228.202.193]"
"SMTPC"	12368	300	"2014-06-10 12:43:38.004"	"74.125.129.109"	"RECEIVED: 250-SIZE 35882577"
"SMTPC"	12912	300	"2014-06-10 12:43:38.005"	"74.125.129.109"	"RECEIVED: 250-8BITMIME"
"SMTPC"	12368	300	"2014-06-10 12:43:38.005"	"74.125.129.109"	"RECEIVED: 250-AUTH LOGIN PLAIN XOAUTH XOAUTH2 PLAIN-CLIENTTOKEN"
"SMTPC"	12960	300	"2014-06-10 12:43:38.006"	"74.125.129.109"	"RECEIVED: 250-ENHANCEDSTATUdomainODES"
"SMTPC"	12368	300	"2014-06-10 12:43:38.007"	"74.125.129.109"	"RECEIVED: 250 CHUNKING"
"SMTPC"	12368	300	"2014-06-10 12:43:38.008"	"74.125.129.109"	"SENT: AUTH LOGIN"
"SMTPC"	11256	300	"2014-06-10 12:43:38.310"	"74.125.129.109"	"RECEIVED: 334 VXNlcm5hbWU6"
"SMTPC"	11256	300	"2014-06-10 12:43:38.311"	"74.125.129.109"	"SENT: c21vcmdvbi5ub3RpZnlAZ21haWwuY29t"
"SMTPC"	12368	300	"2014-06-10 12:43:38.532"	"74.125.129.109"	"RECEIVED: 334 UGFzc3dvcmQ6"
"SMTPC"	12368	300	"2014-06-10 12:43:38.533"	"74.125.129.109"	"SENT: ***"
"SMTPC"	4828	300	"2014-06-10 12:43:38.934"	"74.125.129.109"	"RECEIVED: 235 2.7.0 Accepted"
"SMTPC"	4828	300	"2014-06-10 12:43:38.935"	"74.125.129.109"	"SENT: MAIL FROM:<iLO.domain.local@domain.local>"
"SMTPC"	5452	300	"2014-06-10 12:43:39.292"	"74.125.129.109"	"RECEIVED: 250 2.1.0 OK ia2sm66498447pbb.32 - gsmtp"
"SMTPC"	5452	300	"2014-06-10 12:43:39.295"	"74.125.129.109"	"SENT: RCPT TO:<notifications@external-domain.com>"
"SMTPC"	11256	300	"2014-06-10 12:43:39.499"	"74.125.129.109"	"RECEIVED: 250 2.1.5 OK ia2sm66498447pbb.32 - gsmtp"
"SMTPC"	11256	300	"2014-06-10 12:43:39.500"	"74.125.129.109"	"SENT: DATA"
"SMTPC"	10832	300	"2014-06-10 12:43:39.940"	"74.125.129.109"	"RECEIVED: 354  Go ahead ia2sm66498447pbb.32 - gsmtp"
"SMTPC"	10832	300	"2014-06-10 12:43:39.942"	"74.125.129.109"	"SENT: [nl]."
"SMTPC"	2636	300	"2014-06-10 12:43:40.971"	"74.125.129.109"	"RECEIVED: 250 2.0.0 OK 1402368220 ia2sm66498447pbb.32 - gsmtp"
"SMTPC"	2636	300	"2014-06-10 12:43:40.972"	"74.125.129.109"	"SENT: QUIT"
"SMTPC"	14116	300	"2014-06-10 12:43:41.297"	"74.125.129.109"	"RECEIVED: 221 2.0.0 closing connection ia2sm66498447pbb.32 - gsmtp"
"APPLICATION"	1384	"2014-06-10 12:43:41.305"	"SMTPDeliverer - Message 274: Message delivery thread completed."
Shall I send you all the hMailServer logs I've got?

I had a thorough look at the logs and out of the 6 internal SMTP clients only 10.0.0.2 appears to exhibit this issue. I'm beginning to wonder if it may be the culprit, but I will need more evidence to determine that, hopefully someone here will be able to help me confirm that.

Bill48105
Developer
Developer
Posts: 6192
Joined: 2010-04-24 23:16
Location: Michigan, USA

Re: Some emails are not sent

Post by Bill48105 » 2014-06-10 09:43

not sure if it's the fact that it's almost 4am here or that I just finished my beer but i see no issues in the log snippet you posted. There not even a 1 sec delay from the 354 ok & queued..
hMailServer build LIVE on my servers: 5.4-B2014050402
#hmailserver on FreeNode IRC https://webchat.freenode.net/?channels=#hmailserver
*** ABSENT FROM hMail! Those in IRC know how to find me if urgent. ***

byebyebyte
New user
New user
Posts: 4
Joined: 2014-06-10 07:14

Re: Some emails are not sent

Post by byebyebyte » 2014-06-10 10:07

You're having a much better time than I am :)

Look at the last lines at 12:41 and 14:13. They both end with 354 but there is no indication of subsequent queuing and relaying, unlike 12:43 and 14:17. If mail was indeed queued and relayed to gmail, why isn't it logged? I can tell you for sure no mail was received by my mail client at 14:13, don't remember anymore about 12:41.

But there's no rush, keep enjoying your night out ;)

byebyebyte
New user
New user
Posts: 4
Joined: 2014-06-10 07:14

Re: Some emails are not sent

Post by byebyebyte » 2014-06-13 08:00

Hi just wondering if anyone can advise where the problem is.

I checked more log files and I can confirm every time hMail sends an email it logs the internal SMTP activity (internal client to hMail) and the external relay (hMail to external relay, Gmail in this case). I am assuming this indicates normal behavior and anything outside of this indicates a problem.

In those two instances (12:41 and 14:13) an SMTP session started from 10.0.0.2 (in response to clicking Send Test Mail on HP iLO) but stopped for an unexplained reason (see log snippets above). I'm just trying to determine why those sessions stopped and what I can do (if anything) to prevent these failures.

Could very well be that the problem is with iLO but I was just hoping I could confirm this way or the other.

Thanks again

percepts
Senior user
Senior user
Posts: 5282
Joined: 2009-10-20 16:33
Location: Sceptred Isle

Re: Some emails are not sent

Post by percepts » 2014-06-13 15:59

put your log snippets into http://log.damnation.org.uk/

you will see that it looks like whatever is sending the mail is not terminating the first send properly. i.e. the first smtpd session. There is no quit.

Post Reply