SMTP not sending messages

[TheKorn2]

Openhab is failing to send a message on a rule to a non-TLS SMTP server. Openhab sends EHLO, then HELO, then QUIT. At that point the remote side hangs up, since Openhab requested QUIT, and no message is sent. Seems as though there's either a missing payload between HELO and QUIT, or sending QUIT is premature.

mail settings I'm using:

mail:hostname=mail.thekorn.net mail:port=26 mail:username=(redacted)@thekorn.net mail:password=(redacted #2) mail:from=(redacted)@thekorn.net mail:tls=false

mail:popbeforesmtp=false

mail:charset=

dump generated on openhab host (assuming it only has one network port) by running:

sudo tcpdump host (your mail server) -vvXS -w tcpdump_capture_file.cap

then dragging tcpdump_capture_file.cap into wireshark to examine.

I'm no SMTP expert, but wireshark says that openhab is sending three commands in packet 7:

EHLO HELO QUIT

tcpdump capture file available here, since github insists this isn't a zip file (it is): http://www.thekorn.net/temp/tcpdump_capture_file.zip

[TheKorn2]

For those not super familiar with wireshark, once you load the capture file, go to analyze -> decode as -> transport -> SMTP. (Wireshark doesn't automatically pick it because it's not on port 25.)

[watou]

Thanks for this report. It's possible that there is a bug in Apache Commons Email. It's also possible that this has been fixed by a later version. openHAB is using commons-email-1.2.jar, which is now over six years old. The latest is 1.4 from last May. I can try to build you a new org.openhab.action.mail JAR with a later Apache Commons Email, if you would like to try it?

[watou]

@TheKorn2 Any interest in trying this test JAR, which only differs from previous in that it uses Apache Commons Email 1.4 instead of 1.2?

[TheKorn2]

Absolutely! (Don't have much to lose! ;) )

Will test and report back.

[TheKorn2]

Well, updated to that test jar, but still nova. Here's the log...

2016-03-03 13:31:16.896 [INFO ] [runtime.busevents             ] - TEST_SWITCH_4 received command ON
2016-03-03 13:31:17.056 [INFO ] [g.openhab.model.script.openhab] - Switch 4 changed state:ON
2016-03-03 13:31:17.118 [INFO ] [g.openhab.model.script.openhab] - Sending vince a dumb email.
>>>>>Sending data EHLO openhab<<<<<<
>>>>>Sending data HELO openhab<<<<<<
>>>>>Sending data QUIT<<<<<<
2016-03-03 13:31:17.656 [ERROR] [nhab.action.mail.internal.Mail] - Could not send e-mail to 'xxx-redacted-xxx@thekorn.net'.
org.apache.commons.mail.EmailException: Sending the email to the following server failed : mail.thekorn.net:26
        at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1421) ~[commons-email-1.4.jar:1.4]
        at org.apache.commons.mail.Email.send(Email.java:1448) ~[commons-email-1.4.jar:1.4]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:152) [bundlefile:na]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:85) [bundlefile:na]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:63) [bundlefile:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:729) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._featureCallOperation(XbaseInterpreter.java:713) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.openhab.model.script.interpreter.ScriptInterpreter.internalFeatureCallDispatch(ScriptInterpreter.java:69) [org.openhab.model.script_1.8.1.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateAbstractFeatureCall(XbaseInterpreter.java:658) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor49.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor49.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59) [org.openhab.model.script_1.8.1.jar:na]
        at org.openhab.core.scriptengine.ScriptExecutionThread.run(ScriptExecutionThread.java:44) [org.openhab.core.scriptengine_1.8.1.jar:na]
Caused by: javax.mail.SendFailedException: Send failure (javax.mail.MessagingException: Failure sending HELO command to SMTP server)
        at javax.mail.Transport.send(Transport.java:163) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Transport.send(Transport.java:48) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1411) ~[commons-email-1.4.jar:1.4]
        ... 36 common frames omitted
Caused by: javax.mail.MessagingException: Failure sending HELO command to SMTP server
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHelo(SMTPTransport.java:1914) ~[na:na]
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHandshake(SMTPTransport.java:1829) ~[na:na]
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:393) ~[na:na]
        at javax.mail.Service.connect(Service.java:265) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Service.connect(Service.java:85) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Service.connect(Service.java:70) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Transport.send(Transport.java:94) ~[javax.mail_1.4.0.v201005080615.jar:na]
        ... 38 common frames omitted

And for good measure, a tcpdump capture file of this transaction is available at http://www.thekorn.net/temp/mail.thekorn.net.zip .

Happy to grab whatever other info would be helpful, just let me know what would help!

[watou]

Is your issue in any way like this?

Do you have verbose SMTP server logs (if you control that)?

[9037568]

It'd be interesting to see what the failure code is in both cases, since the mail client starts by sending EHLO, but that fails for some reason, so the client falls back to trying HELO. But then HELO also fails...

[TheKorn2]

I'm not thinking that issue is relevant, since it seems to be specific to exchange. (I believe my host runs Exim, but I can double-check if need be.) The server supports EHLO, and also the standard HELO. If I telnet in to port 26 and issue the commands by hand, everything looks normal:

220-atl1.wirenine.com ESMTP Exim 4.86_1 #1 Thu, 03 Mar 2016 15:30:06 -0500
220-We do not authorize the use of this system to transport unsolicited,
220 and/or bulk e-mail.
EHLO
250-atl1.wirenine.com Hello 207-229-136-173.c3-0.hwd-ubr1.chi-hwd.il.cable.rcn.com [207.229.136.173]
250-SIZE 52428800
250-8BITMIME
250-PIPELINING
250-AUTH PLAIN LOGIN
250-STARTTLS
250 HELP
HELO BLAH
250 atl1.wirenine.com Hello 207-229-136-173.c3-0.hwd-ubr1.chi-hwd.il.cable.rcn.com [207.229.136.173]
MAIL FROM:<yo@momma.com>
250 OK
RCPT TO:<xxx-redacted-xxx@thekorn.net>
.
451 Temporarily unable to process your email. Please try again later.
500 unrecognized command
quit
221 atl1.wirenine.com closing connection

(...that's about all I remember cold about how an SMTP transaction is supposed to work. Obviously my RCPT TO line is incorrect. Whoops. :D )

The really weird thing is that all three commands (EHLO, HELO, QUIT) are being sent combined in one packet. Typically SMTP follows a more call/response flow; EHLO (wait for reply), HELO (something), SOMETHING ELSE (something else reply), etc. The upshot is that since they're sent in one packet, there's no possible way that the response codes could have been received before the QUIT command is generated!

Is there maybe a way to flush the buffer after each command? Or is there some sort of opportunistic packet combining going on?

Unfortunately this domain is hosted by wirenine.com , so there's no real hope of getting detailed SMTP server logs.

[9037568]

You could try enabling debug logging for the javamail package and see if that generates anything interesting. I think it's 'mail.debug' or something similar...

[TheKorn2]

So add this to my logback_debug.xml ?

    <logger name="mail.debug" level="DEBUG" additivity="false">
        <appender-ref ref="FILE" />
    </logger>

[9037568]

No, if you're using logback, I guess it'd be "javax.mail" instead of "mail.debug".

I was thinking of doing it from the command line options, but logback should be easier in this case.

On Thu, Mar 3, 2016 at 3:48 PM, TheKorn2 notifications@github.com wrote:

So add this to my logback_debug.xml ?

<logger name="mail.debug" level="DEBUG" additivity="false">
    <appender-ref ref="FILE" />
</logger>

— Reply to this email directly or view it on GitHub https://github.com/openhab/openhab/issues/4130#issuecomment-191956127.

[TheKorn2]

Mmm, doesn't look right since it didn't spit out much more info than we already had:

osgi> 15:04:11.311 [INFO ] [runtime.busevents             :22   ] - TEST_SWITCH_4 received command ON
15:04:11.327 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'send vince an email and shut off switch'
15:04:11.346 [DEBUG] [.p.m.i.MysqlPersistenceService:412  ] - mySQL: Stored item 'TEST_SWITCH_4' as 'ON'[ON] in SQL database at Thu Mar 03 15:04:11 CST 2016.
15:04:11.347 [DEBUG] [.p.m.i.MysqlPersistenceService:414  ] - mySQL: query: INSERT INTO Item103 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;
15:04:11.504 [INFO ] [g.openhab.model.script.openhab:53   ] - Switch 4 changed state:ON
15:04:11.585 [INFO ] [g.openhab.model.script.openhab:53   ] - Sending vince a dumb email.
>>>>>Sending data EHLO openhab<<<<<<
>>>>>Sending data HELO openhab<<<<<<
>>>>>Sending data QUIT<<<<<<
15:04:12.113 [ERROR] [nhab.action.mail.internal.Mail:156  ] - Could not send e-mail to 'xxx-redacted-xxx@thekorn.net'.
org.apache.commons.mail.EmailException: Sending the email to the following server failed : mail.thekorn.net:26
        at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1421) ~[commons-email-1.4.jar:1.4]
        at org.apache.commons.mail.Email.send(Email.java:1448) ~[commons-email-1.4.jar:1.4]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:152) [bundlefile:na]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:85) [bundlefile:na]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:63) [bundlefile:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:729) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._featureCallOperation(XbaseInterpreter.java:713) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.openhab.model.script.interpreter.ScriptInterpreter.internalFeatureCallDispatch(ScriptInterpreter.java:69) [org.openhab.model.script_1.8.1.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateAbstractFeatureCall(XbaseInterpreter.java:658) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor46.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor46.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59) [org.openhab.model.script_1.8.1.jar:na]
        at org.openhab.core.scriptengine.ScriptExecutionThread.run(ScriptExecutionThread.java:44) [org.openhab.core.scriptengine_1.8.1.jar:na]
Caused by: javax.mail.SendFailedException: Send failure (javax.mail.MessagingException: Failure sending HELO command to SMTP server)
        at javax.mail.Transport.send(Transport.java:163) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Transport.send(Transport.java:48) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1411) ~[commons-email-1.4.jar:1.4]
        ... 36 common frames omitted
Caused by: javax.mail.MessagingException: Failure sending HELO command to SMTP server
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHelo(SMTPTransport.java:1914) ~[na:na]
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHandshake(SMTPTransport.java:1829) ~[na:na]
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:393) ~[na:na]
        at javax.mail.Service.connect(Service.java:265) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Service.connect(Service.java:85) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Service.connect(Service.java:70) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Transport.send(Transport.java:94) ~[javax.mail_1.4.0.v201005080615.jar:na]
        ... 38 common frames omitted
15:04:12.272 [DEBUG] [script.actions.ScriptExecution:131  ] - Scheduled code for execution at 2016-03-03T15:04:17.263-06:00
15:04:17.264 [DEBUG] [.s.i.actions.TimerExecutionJob:42   ] - Executing timer 'DEFAULT.2016-03-03T15:04:17.263-06:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: org.eclipse
.xtext.xbase.impl.XClosureImplCustom@3f1cd625 (explicitSyntax: true)'
15:04:17.333 [INFO ] [g.openhab.model.script.openhab:53   ] - Turning off test switch 4
15:04:17.408 [INFO ] [runtime.busevents             :22   ] - TEST_SWITCH_4 received command OFF
15:04:17.431 [DEBUG] [.p.m.i.MysqlPersistenceService:412  ] - mySQL: Stored item 'TEST_SWITCH_4' as 'OFF'[OFF] in SQL database at Thu Mar 03 15:04:17 CST 2016.
15:04:17.432 [DEBUG] [.p.m.i.MysqlPersistenceService:414  ] - mySQL: query: INSERT INTO Item103 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;

[watou]

Any chance you could configure tls=true and change the port? Does the provider allow that?

[TheKorn2]

Yes, my host does support doing TLS auth (via a different port). That's actually where I started and backed down to non-TLS since it's usually easier to debug a non-TLS session than a TLS one. But I'll try reconfiguring with the TLS settings and see if that makes any difference with the updated jar.

[9037568]

Based on the traces, you could also add

org.apache.commons.mail org.apache.geronimo.javamail

[TheKorn2]

TLS configuration didn't have anything substantially different...

15:32:38.024 [ERROR] [nhab.action.mail.internal.Mail:156  ] - Could not send e-mail to 'xxx-redacted-xxx@thekorn.net'.
org.apache.commons.mail.EmailException: Sending the email to the following server failed : atl1.wirenine.com:465
        at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1421) ~[commons-email-1.4.jar:1.4]
        at org.apache.commons.mail.Email.send(Email.java:1448) ~[commons-email-1.4.jar:1.4]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:152) [bundlefile:na]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:85) [bundlefile:na]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:63) [bundlefile:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:729) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._featureCallOperation(XbaseInterpreter.java:713) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor48.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.openhab.model.script.interpreter.ScriptInterpreter.internalFeatureCallDispatch(ScriptInterpreter.java:69) [org.openhab.model.script_1.8.1.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateAbstractFeatureCall(XbaseInterpreter.java:658) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor47.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59) [org.openhab.model.script_1.8.1.jar:na]
        at org.openhab.core.scriptengine.ScriptExecutionThread.run(ScriptExecutionThread.java:44) [org.openhab.core.scriptengine_1.8.1.jar:na]
Caused by: javax.mail.SendFailedException: Send failure (javax.mail.MessagingException: Failure sending HELO command to SMTP server)
        at javax.mail.Transport.send(Transport.java:163) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Transport.send(Transport.java:48) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1411) ~[commons-email-1.4.jar:1.4]
        ... 38 common frames omitted
Caused by: javax.mail.MessagingException: Failure sending HELO command to SMTP server
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHelo(SMTPTransport.java:1914) ~[na:na]
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHandshake(SMTPTransport.java:1829) ~[na:na]
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:393) ~[na:na]
        at javax.mail.Service.connect(Service.java:265) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Service.connect(Service.java:85) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Service.connect(Service.java:70) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Transport.send(Transport.java:94) ~[javax.mail_1.4.0.v201005080615.jar:na]
        ... 40 common frames omitted
15:32:38.156 [DEBUG] [script.actions.ScriptExecution:131  ] - Scheduled code for execution at 2016-03-03T15:32:43.148-06:00

(Reverted to non-tls config for easy packet sniffing.)

[TheKorn2]

I'm not confident we're getting the debug output we should be getting. I added this to logback_debug.xml:

    <!--  Email debugging -->
    <logger name="javax.mail" level="DEBUG" additivity="false">
        <appender-ref ref="FILE" />
    </logger>
    <logger name="org.apache.commons.mail" level="DEBUG" additivity="false">
        <appender-ref ref="FILE" />
    </logger>
    <logger name="org.apache.geronimo.javamail" level="DEBUG" additivity="false">
        <appender-ref ref="FILE" />
    </logger>

Here's what gets spit out both to the console and to openhab.log:

15:41:03.448 [INFO ] [runtime.busevents             :22   ] - TEST_SWITCH_4 received command ON
15:41:03.461 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'send vince an email and shut off switch'
15:41:03.478 [DEBUG] [.p.m.i.MysqlPersistenceService:412  ] - mySQL: Stored item 'TEST_SWITCH_4' as 'ON'[ON] in SQL database at Thu Mar 03 15:41:03 CST 2016.
15:41:03.479 [DEBUG] [.p.m.i.MysqlPersistenceService:414  ] - mySQL: query: INSERT INTO Item103 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;
15:41:03.633 [INFO ] [g.openhab.model.script.openhab:53   ] - Switch 4 changed state:ON
15:41:03.700 [INFO ] [g.openhab.model.script.openhab:53   ] - Sending vince a dumb email.
15:41:04.332 [ERROR] [nhab.action.mail.internal.Mail:156  ] - Could not send e-mail to 'xxx-redacted-xxx@thekorn.net'.
org.apache.commons.mail.EmailException: Sending the email to the following server failed : mail.thekorn.net:26
        at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1421) ~[commons-email-1.4.jar:1.4]
        at org.apache.commons.mail.Email.send(Email.java:1448) ~[commons-email-1.4.jar:1.4]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:152) [bundlefile:na]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:85) [bundlefile:na]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:63) [bundlefile:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:729) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._featureCallOperation(XbaseInterpreter.java:713) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.openhab.model.script.interpreter.ScriptInterpreter.internalFeatureCallDispatch(ScriptInterpreter.java:69) [org.openhab.model.script_1.8.1.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateAbstractFeatureCall(XbaseInterpreter.java:658) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor46.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor46.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59) [org.openhab.model.script_1.8.1.jar:na]
        at org.openhab.core.scriptengine.ScriptExecutionThread.run(ScriptExecutionThread.java:44) [org.openhab.core.scriptengine_1.8.1.jar:na]
Caused by: javax.mail.SendFailedException: Send failure (javax.mail.MessagingException: Failure sending HELO command to SMTP server)
        at javax.mail.Transport.send(Transport.java:163) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Transport.send(Transport.java:48) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1411) ~[commons-email-1.4.jar:1.4]
        ... 36 common frames omitted
Caused by: javax.mail.MessagingException: Failure sending HELO command to SMTP server
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHelo(SMTPTransport.java:1914) ~[na:na]
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHandshake(SMTPTransport.java:1829) ~[na:na]
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:393) ~[na:na]
        at javax.mail.Service.connect(Service.java:265) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Service.connect(Service.java:85) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Service.connect(Service.java:70) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Transport.send(Transport.java:94) ~[javax.mail_1.4.0.v201005080615.jar:na]
        ... 38 common frames omitted
15:41:04.504 [DEBUG] [script.actions.ScriptExecution:131  ] - Scheduled code for execution at 2016-03-03T15:41:09.495-06:00
15:41:07.149 [INFO ] [runtime.busevents             :26   ] - PINBALL_ALLEY_AUX_AC_WATTS_PHASE1 state updated to 0
15:41:07.249 [INFO ] [runtime.busevents             :26   ] - PINBALL_ALLEY_AUX_AC_WATTS_PHASE2 state updated to 0
15:41:07.468 [INFO ] [runtime.busevents             :26   ] - BASMENT_FREEZER_KWH state updated to 255.471

...which doesn't look any different from when those three sections aren't in my logback_debug.xml , so... yeah. Before anyone asks, yes I'm running openhab using start_debug.sh .

[9037568]

You could crank the logging levels for the mail packages up to TRACE instead of DEBUG. Might get a bit more, though I'm not counting on it at this point.

[9037568]

Comments at the link below indicate that some mail proxies don't allow commands to arrive split across multiple packets (as here, where the E in the first EHLO comes in one packet and then HLO comes in the next packet). Although this still doesn't explain why EHLO/HELO/QUIT appear to be sent simultaneously.

https://social.technet.microsoft.com/Forums/en-US/06b2669b-a584-4426-abb8-b22af9fa9fb5/telnet-to-port-25-gives-back-the-response-as-220-no-banner-info-at-all?forum=exchangesvrsecuremessaginglegacy

[mrguessed]

I just tried a non-TLS, but Login-required, SMTP server (Comcast) with this test code and it went through to my inbox:

rule "Test Mail"
when
    Time cron "0 0/1 * * * ?"
then
    sendMail('nothing2seemovealong@example.com', 'Test Subject', 'Test Body')
end

Given how the packet is being packed, I'm wondering if there's a a difference in how sendMail() it's being called.

eg. Non Latin-1 chars, or one of the other sendMail() variants.

@TheKorn2: You may want to add the text of your test Rule, just in case there's something else folks can glean from it.

For my testcase, I used a 1.9.0-SNAPSHOT version of the Mail action binding code, and I'm running under a newer version of Java, and Comcast required me to use Port 587:

java version "1.8.0_71"
Java(TM) SE Runtime Environment (build 1.8.0_71-b15)
Java HotSpot(TM) Client VM (build 25.71-b15, mixed mode)

@9037568: I also see the packet fragging on the E of EHLO (and later for A in AUTH LOGIN etc). I'm assuming that's a buffering bug.

[TheKorn2]

@9037568 Yup, changing debug to trace didn't shed much more light, but presented for completeness sake:

osgi> 04:49:23.330 [INFO ] [runtime.busevents             :22   ] - TEST_SWITCH_4 received command ON
04:49:23.343 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'send vince an email and shut off switch'
04:49:23.361 [DEBUG] [.p.m.i.MysqlPersistenceService:412  ] - mySQL: Stored item 'TEST_SWITCH_4' as 'ON'[ON] in SQL database at Fri Mar 04 04:49:23 CST 2016.
04:49:23.362 [DEBUG] [.p.m.i.MysqlPersistenceService:414  ] - mySQL: query: INSERT INTO Item103 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;
04:49:23.513 [INFO ] [g.openhab.model.script.openhab:53   ] - Switch 4 changed state:ON
04:49:23.578 [INFO ] [g.openhab.model.script.openhab:53   ] - Sending vince a dumb email.
>>>>>Sending data EHLO openhab<<<<<<
>>>>>Sending data HELO openhab<<<<<<
>>>>>Sending data QUIT<<<<<<
04:49:24.196 [ERROR] [nhab.action.mail.internal.Mail:156  ] - Could not send e-mail to 'xxx-redacted-xxx@thekorn.net'.
org.apache.commons.mail.EmailException: Sending the email to the following server failed : mail.thekorn.net:26
        at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1421) ~[commons-email-1.4.jar:1.4]
        at org.apache.commons.mail.Email.send(Email.java:1448) ~[commons-email-1.4.jar:1.4]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:152) [bundlefile:na]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:85) [bundlefile:na]
        at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:63) [bundlefile:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:729) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._featureCallOperation(XbaseInterpreter.java:713) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor47.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.openhab.model.script.interpreter.ScriptInterpreter.internalFeatureCallDispatch(ScriptInterpreter.java:69) [org.openhab.model.script_1.8.1.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateAbstractFeatureCall(XbaseInterpreter.java:658) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor46.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor48.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at sun.reflect.GeneratedMethodAccessor48.invoke(Unknown Source) ~[na:na]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
        at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
        at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
        at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59) [org.openhab.model.script_1.8.1.jar:na]
        at org.openhab.core.scriptengine.ScriptExecutionThread.run(ScriptExecutionThread.java:44) [org.openhab.core.scriptengine_1.8.1.jar:na]
Caused by: javax.mail.SendFailedException: Send failure (javax.mail.MessagingException: Failure sending HELO command to SMTP server)
        at javax.mail.Transport.send(Transport.java:163) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Transport.send(Transport.java:48) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1411) ~[commons-email-1.4.jar:1.4]
        ... 36 common frames omitted
Caused by: javax.mail.MessagingException: Failure sending HELO command to SMTP server
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHelo(SMTPTransport.java:1914) ~[na:na]
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHandshake(SMTPTransport.java:1829) ~[na:na]
        at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:393) ~[na:na]
        at javax.mail.Service.connect(Service.java:265) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Service.connect(Service.java:85) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Service.connect(Service.java:70) ~[javax.mail_1.4.0.v201005080615.jar:na]
        at javax.mail.Transport.send(Transport.java:94) ~[javax.mail_1.4.0.v201005080615.jar:na]
        ... 38 common frames omitted
04:49:24.348 [DEBUG] [script.actions.ScriptExecution:131  ] - Scheduled code for execution at 2016-03-04T04:49:29.339-06:00
04:49:27.320 [INFO ] [runtime.busevents             :22   ] - TEST_SWITCH_4 received command OFF
04:49:27.337 [DEBUG] [.p.m.i.MysqlPersistenceService:412  ] - mySQL: Stored item 'TEST_SWITCH_4' as 'OFF'[OFF] in SQL database at Fri Mar 04 04:49:27 CST 2016.
04:49:27.338 [DEBUG] [.p.m.i.MysqlPersistenceService:414  ] - mySQL: query: INSERT INTO Item103 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;
04:49:29.340 [DEBUG] [.s.i.actions.TimerExecutionJob:42   ] - Executing timer 'DEFAULT.2016-03-04T04:49:29.339-06:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: org.eclipse
.xtext.xbase.impl.XClosureImplCustom@2b9a98f1 (explicitSyntax: true)'
04:49:29.400 [INFO ] [g.openhab.model.script.openhab:53   ] - Turning off test switch 4
04:49:29.476 [INFO ] [runtime.busevents             :22   ] - TEST_SWITCH_4 received command OFF

@mrguessed Shouldn't be anything even close to funky going on with regards to charset. Everything should be fully represent-able by 7-bit ASCII, let alone 8-bit UTF-8.

Test rule is really unremarkable, but presented for completeness' sake. Item definition:

Switch TEST_SWITCH_4 "Test virtual switch 4 -- send email (don't push this!)" (Group_Test)

And the rule:

rule "send vince an email and shut off switch"
when
    // only process on a switch on state
    Item TEST_SWITCH_4 received update ON
then
    {
        logInfo("openhab","Switch 4 changed state:" + TEST_SWITCH_4.state)      
        logInfo("openhab","Sending vince a dumb email.")
        sendMail("xxx--redacted--xxx@thekorn.net","subject: test","This is the message body.  Switch 4 state is now:"  + TEST_SWITCH_4.state)
            Switch4Timer = createTimer(now.plusSeconds(5)) [|
                logInfo("openhab","Turning off test switch 4")
                sendCommand("TEST_SWITCH_4","OFF")
            ]
    }   
end

(I usually get impatient after it fails and shut the switch off myself, for what it's worth!)

vince@openhab:~$ java -showversion
java version "1.7.0_95"
OpenJDK Runtime Environment (IcedTea 2.6.4) (7u95-2.6.4-0ubuntu0.14.04.1)
OpenJDK 64-Bit Server VM (build 24.95-b01, mixed mode)

[watou]

This may be unrelated to this issue, but I see that Apache Commons Email 1.4 depends on javax.mail 1.5.2, even though it does not set the dependency in its own MANIFEST.MF. openHAB 1 and 2 both use javax.mail 1.4.0.v201005080615 (openHAB 2). The test JAR I shared used Apache Commons Email 1.4 but still using the older javax.mail 1.4.0, and it was at least binary compatible enough to run for @TheKorn2, but that's obviously not good enough.

I am looking into updating javax.mail to this, but I don't yet know how to update the dependencies in both openHAB 1.8 and 2.

Also, instead of directly including commons-email-1.4.jar in org.openhab.actions.mail, perhaps it's better to pull it from the Maven repository and use it as an OSGi bundle?

@kaikreuzer, any suggestions?

[mrguessed]

Does it occur when your run an Oracle JDK instead of OpenJDK?

[TheKorn2]

Good question! I decided that was a large enough change that I didn't want to do it on my production hardware. I quickly imaged the drive and brought that drive image into a virtual machine with no changes. (zwave wouldn't run obviously because of no hardware, but that hardly matters here.) Verified the original problem still happens when in the VM. Then I removed openJDK and replaced it with Oracle's java 7 runtime. Same results.

07:56:07.620 [DEBUG] [.p.m.i.MysqlPersistenceService:412  ] - mySQL: Stored item 'TEST_SWITCH_4' as 'ON'[ON] in SQL database at Fri Mar 04 07:56:07 PST 2016.
07:56:07.620 [DEBUG] [.p.m.i.MysqlPersistenceService:414  ] - mySQL: query: INSERT INTO Item69 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;
07:56:07.621 [INFO ] [runtime.busevents             :22   ] - TEST_SWITCH_4 received command ON
07:56:07.645 [INFO ] [g.openhab.model.script.openhab:53   ] - Switch 4 changed state:ON
07:56:07.658 [INFO ] [g.openhab.model.script.openhab:53   ] - Sending vince a dumb email.
>>>>>Sending data EHLO openhab<<<<<<
>>>>>Sending data HELO openhab<<<<<<
>>>>>Sending data QUIT<<<<<<
07:56:07.982 [ERROR] [nhab.action.mail.internal.Mail:156  ] - Could not send e-mail to 'xx-redacted-xx@thekorn.net'.
org.apache.commons.mail.EmailException: Sending the email to the following server failed : mail.thekorn.net:26
    at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1421) ~[commons-email-1.4.jar:1.4]
    at org.apache.commons.mail.Email.send(Email.java:1448) ~[commons-email-1.4.jar:1.4]
    at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:152) [bundlefile:na]
    at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:85) [bundlefile:na]
    at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:63) [bundlefile:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_80]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_80]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_80]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_80]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:729) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._featureCallOperation(XbaseInterpreter.java:713) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_80]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_80]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.openhab.model.script.interpreter.ScriptInterpreter.internalFeatureCallDispatch(ScriptInterpreter.java:69) [org.openhab.model.script_1.8.1.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateAbstractFeatureCall(XbaseInterpreter.java:658) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_80]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_80]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_80]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_80]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_80]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_80]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_80]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_80]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_80]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_80]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59) [org.openhab.model.script_1.8.1.jar:na]
    at org.openhab.core.scriptengine.ScriptExecutionThread.run(ScriptExecutionThread.java:44) [org.openhab.core.scriptengine_1.8.1.jar:na]
Caused by: javax.mail.SendFailedException: Send failure (javax.mail.MessagingException: Failure sending HELO command to SMTP server)
    at javax.mail.Transport.send(Transport.java:163) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Transport.send(Transport.java:48) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1411) ~[commons-email-1.4.jar:1.4]
    ... 38 common frames omitted
Caused by: javax.mail.MessagingException: Failure sending HELO command to SMTP server
    at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHelo(SMTPTransport.java:1914) ~[na:na]
    at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHandshake(SMTPTransport.java:1829) ~[na:na]
    at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:393) ~[na:na]
    at javax.mail.Service.connect(Service.java:265) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Service.connect(Service.java:85) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Service.connect(Service.java:70) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Transport.send(Transport.java:94) ~[javax.mail_1.4.0.v201005080615.jar:na]
    ... 40 common frames omitted
07:56:08.013 [DEBUG] [script.actions.ScriptExecution:131  ] - Scheduled code for execution at 2016-03-04T07:56:13.010-08:00
07:56:13.011 [DEBUG] [.s.i.actions.TimerExecutionJob:42   ] - Executing timer 'DEFAULT.2016-03-04T07:56:13.010-08:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: org.eclipse.xtext.xbase.impl.XClosureImplCustom@7fcd4682 (explicitSyntax: true)'
07:56:13.033 [INFO ] [g.openhab.model.script.openhab:53   ] - Turning off test switch 4
07:56:13.067 [DEBUG] [.p.m.i.MysqlPersistenceService:412  ] - mySQL: Stored item 'TEST_SWITCH_4' as 'OFF'[OFF] in SQL database at Fri Mar 04 07:56:13 PST 2016.
07:56:13.067 [DEBUG] [.p.m.i.MysqlPersistenceService:414  ] - mySQL: query: INSERT INTO Item69 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;
07:56:13.068 [INFO ] [runtime.busevents             :22   ] - TEST_SWITCH_4 received command OFF

openhab@openhab:/openhab$ java -version
java version "1.7.0_80"
Java(TM) SE Runtime Environment (build 1.7.0_80-b15)
Java HotSpot(TM) 64-Bit Server VM (build 24.80-b11, mixed mode)
openhab@openhab:/openhab$ 

(Main point being that on the real hardware, openjdk is still what's running.)

[mrguessed]

There are a few differences between your env and mine, and perhaps these are contributing to the issue. I suspect that the issue is on the calling side because, as you noted, the EHLO HELO QUIT smtp sequence is all in one packet, very early on in the sequence.... which is never going to work.

Here are the differences I can see

• Java 7 vs Java 8 - Java 1.7 was EOL'd ~ mid last yr. It might be worthwhile trying a newer release.
• Strip the testcase down to just the sendMail action call, to avoid any potential interaction from the Item.
• Your newer tests are using the commons-email-1.4.jar (from @watou) mine are using the 3yr old commons-email-1.2.jar that's been in the openHAB stack for a while now.
• I'm running a 1.9.0-SNAPSHOT rel, in a 1.8.1 runtime. Doesn't look to be any material changes in that release, but you never know. I'll download the pure 1.8.1 version of the Binding this weekend to see if it makes a difference.
• ARM vs Intel - I doubt it's an issue...

@watou, @9037568 : When you validate this in your environments, does it work correctly for you? If so, can you provide some version# details to help narrow down the situation?

[mrguessed]

oh, since the EHLO is sent out after the smtp greeting (as expected), there's also the possibility that that's triggering a latent bug in the commons-email code.

In your case, the smtp is using a multi-line 220 (3x lines) response, and mine is single line 220.

Is there another Email server you could point at to test that theory? Looks like smtp.gmail.com is using a single line 220 response so it might work.

[TheKorn2]

Well, I have good news, and I have bad news.

The bad news: the only other server I have access to (that runs on a completely independent hosting service) _also happens to be running Exim 4.861

220-cpanel29.fastdnsservers2.com ESMTP Exim 4.86_1 #1 Fri, 04 Mar 2016 11:11:14 -0600
220-We do not authorize the use of this system to transport unsolicited,
220 and/or bulk e-mail.
quit
221 cpanel29.fastdnsservers2.com closing connection

The good news: even though a completely independent hosting company (and they have wildly different configurations and permissions) the bug manifests identically trying to send to both servers!

2016-03-04 09:15:03.477 [INFO ] [runtime.busevents             ] - TEST_SWITCH_4 received command ON
2016-03-04 09:15:03.526 [INFO ] [g.openhab.model.script.openhab] - Switch 4 changed state:ON
2016-03-04 09:15:03.538 [INFO ] [g.openhab.model.script.openhab] - Sending vince a dumb email.
>>>>>Sending data EHLO openhab<<<<<<
>>>>>Sending data HELO openhab<<<<<<
>>>>>Sending data QUIT<<<<<<
2016-03-04 09:15:03.837 [ERROR] [nhab.action.mail.internal.Mail] - Could not send e-mail to 'xx-redacted-xx@thekorn.net'.
org.apache.commons.mail.EmailException: Sending the email to the following server failed : 216.51.232.29:587
    at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1421) ~[commons-email-1.4.jar:1.4]
    at org.apache.commons.mail.Email.send(Email.java:1448) ~[commons-email-1.4.jar:1.4]
    at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:152) [bundlefile:na]
    at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:85) [bundlefile:na]
    at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:63) [bundlefile:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:729) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._featureCallOperation(XbaseInterpreter.java:713) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.openhab.model.script.interpreter.ScriptInterpreter.internalFeatureCallDispatch(ScriptInterpreter.java:69) [org.openhab.model.script_1.8.1.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateAbstractFeatureCall(XbaseInterpreter.java:658) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59) [org.openhab.model.script_1.8.1.jar:na]
    at org.openhab.core.scriptengine.ScriptExecutionThread.run(ScriptExecutionThread.java:44) [org.openhab.core.scriptengine_1.8.1.jar:na]
Caused by: javax.mail.SendFailedException: Send failure (javax.mail.MessagingException: Failure sending HELO command to SMTP server)
    at javax.mail.Transport.send(Transport.java:163) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Transport.send(Transport.java:48) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1411) ~[commons-email-1.4.jar:1.4]
    ... 38 common frames omitted
Caused by: javax.mail.MessagingException: Failure sending HELO command to SMTP server
    at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHelo(SMTPTransport.java:1914) ~[na:na]
    at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHandshake(SMTPTransport.java:1829) ~[na:na]
    at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:393) ~[na:na]
    at javax.mail.Service.connect(Service.java:265) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Service.connect(Service.java:85) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Service.connect(Service.java:70) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Transport.send(Transport.java:94) ~[javax.mail_1.4.0.v201005080615.jar:na]
    ... 40 common frames omitted
2016-03-04 09:15:08.896 [INFO ] [g.openhab.model.script.openhab] - Turning off test switch 4
2016-03-04 09:15:08.923 [INFO ] [runtime.busevents             ] - TEST_SWITCH_4 received command OFF

(No worries, that test server also believes that it's the MX for thekorn.net... it's an old hosting account that hasn't run out yet and I haven't bothered to nuke. :D )

[TheKorn2]

It occurs to me that a quick way to pretty much eliminate most (if not all) of those variables that you noted would be to give you a temporary email account you could auth against on thekorn.net . I wouldn't be opposed to doing that on a temporary basis.

Thinking about it even further you don't even need an account at all; the transaction flushes before any authentication is even attempted. So have at it; just make up some unique gobbledygook for the username and the password; if you get as far as that being rejected then you're getting a different result.

[watou]

One area to consider:

The current implementation of sendMail is setting setTLS(true); but this confusingly means "connect with a normal socket, but then attempt to switch to secure using STARTTLS". That's why the Apache Commons Email people later sensibly deprecated setTLS in preference to setStartTLSEnabled.

It seems possible that these SMTP servers won't work that way. They may require a properly negotiated TLS connection up front, not the plain-text-to-STARTTLS transition that the sendMail action is trying to do. I could make you a test JAR that attempts to connect securely at the outset, instead of using STARTTLS. Would you try that?

[TheKorn2]

I have nothing working (as far as SMTP goes) right now, so you can from here on out safely assume I'm willing to try whatever. ;)

[TheKorn2]

You are remembering that I reverted back to my non-TLS config though, right? (I can switch back and forth easily, it's just usually harder to debug protocol+tls than just protocol.)

[watou]

OK, try this, but change your openhab.cfg to have

mail:tls=false
mail:ssl=true

and make sure you are setting a port that supports SMTPS.

[TheKorn2]

Done. (Tested on my VM so I could roll back the change easily.) No substantive change in behavior.

12:44:24.068 [INFO ] [runtime.busevents             :22   ] - TEST_SWITCH_4 received command ON
12:44:24.071 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'send vince an email and shut off switch'
12:44:24.075 [INFO ] [g.openhab.model.script.openhab:53   ] - Switch 4 changed state:ON
12:44:24.077 [INFO ] [g.openhab.model.script.openhab:53   ] - Sending vince a dumb email.
12:44:24.078 [DEBUG] [.p.m.i.MysqlPersistenceService:412  ] - mySQL: Stored item 'TEST_SWITCH_4' as 'ON'[ON] in SQL database at Fri Mar 04 12:44:24 CST 2016.
12:44:24.079 [DEBUG] [.p.m.i.MysqlPersistenceService:414  ] - mySQL: query: INSERT INTO Item69 (TIME, VALUE) VALUES(NOW(),?) ON DUPLICATE KEY UPDATE VALUE=?;
>>>>>Sending data EHLO openhab<<<<<<
>>>>>Sending data HELO openhab<<<<<<
>>>>>Sending data QUIT<<<<<<
12:44:24.395 [ERROR] [nhab.action.mail.internal.Mail:161  ] - Could not send e-mail to 'xx-redacted-xx@thekorn.net'.
org.apache.commons.mail.EmailException: Sending the email to the following server failed : atl1.wirenine.com:465
    at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1421) ~[commons-email-1.4.jar:1.4]
    at org.apache.commons.mail.Email.send(Email.java:1448) ~[commons-email-1.4.jar:1.4]
    at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:157) [bundlefile:na]
    at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:89) [bundlefile:na]
    at org.openhab.action.mail.internal.Mail.sendMail(Mail.java:67) [bundlefile:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:729) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._featureCallOperation(XbaseInterpreter.java:713) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.GeneratedMethodAccessor45.invoke(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.openhab.model.script.interpreter.ScriptInterpreter.internalFeatureCallDispatch(ScriptInterpreter.java:69) [org.openhab.model.script_1.8.1.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateAbstractFeatureCall(XbaseInterpreter.java:658) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.7.0_95]
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) ~[na:1.7.0_95]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.7.0_95]
    at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_95]
    at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) [org.eclipse.xtext.util_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204) [org.eclipse.xtext.xbase_2.3.0.v201206120633.jar:na]
    at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59) [org.openhab.model.script_1.8.1.jar:na]
    at org.openhab.core.scriptengine.ScriptExecutionThread.run(ScriptExecutionThread.java:44) [org.openhab.core.scriptengine_1.8.1.jar:na]
Caused by: javax.mail.SendFailedException: Send failure (javax.mail.MessagingException: Failure sending HELO command to SMTP server)
    at javax.mail.Transport.send(Transport.java:163) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Transport.send(Transport.java:48) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1411) ~[commons-email-1.4.jar:1.4]
    ... 38 common frames omitted
Caused by: javax.mail.MessagingException: Failure sending HELO command to SMTP server
    at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHelo(SMTPTransport.java:1914) ~[na:na]
    at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.sendHandshake(SMTPTransport.java:1829) ~[na:na]
    at org.apache.geronimo.javamail.transport.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:393) ~[na:na]
    at javax.mail.Service.connect(Service.java:265) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Service.connect(Service.java:85) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Service.connect(Service.java:70) ~[javax.mail_1.4.0.v201005080615.jar:na]
    at javax.mail.Transport.send(Transport.java:94) ~[javax.mail_1.4.0.v201005080615.jar:na]
    ... 40 common frames omitted
12:44:24.400 [DEBUG] [script.actions.ScriptExecution:131  ] - Scheduled code for execution at 2016-03-04T12:44:29.398-06:00
12:44:29.399 [DEBUG] [.s.i.actions.TimerExecutionJob:42   ] - Executing timer 'DEFAULT.2016-03-04T12:44:29.398-06:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: org.eclipse.xtext.xbase.impl.XClosureImplCustom@7d253a3d (explicitSyntax: true)'
12:44:29.400 [INFO ] [g.openhab.model.script.openhab:53   ] - Turning off test switch 4

I also did a tcpdump just to make sure the session was TLS from the start, and it is. I can provide a copy if you'd like but since it's TLS there really isn't much to see without the keys.

[watou]

Why do you use port 465? Have you tried port 587? This is based on what is described here.

[TheKorn2]

465 is the secure port shown as by cpanel. For giggles I also tried 587, same results.

[watou]

Hmm. I see that mail.thekorn.net is a CNAME to thekorn.net, which resolves to 64.38.249.68, and atl1.wirenine.com is an A record to the same IP address. Do you need/have MX records?

[TheKorn2]

Aye, though MX records shouldn't really be entering the mix for this, but yes thekorn.net has an MX record.

vince@openhab:~$ dig -t mx thekorn.net

; <<>> DiG 9.9.5-3ubuntu0.7-Ubuntu <<>> -t mx thekorn.net
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 48114
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;thekorn.net.                   IN      MX

;; ANSWER SECTION:
thekorn.net.            3487    IN      MX      0 thekorn.net.

;; Query time: 13 msec
;; SERVER: 127.0.1.1#53(127.0.1.1)
;; WHEN: Fri Mar 04 15:59:07 CST 2016
;; MSG SIZE  rcvd: 56

[watou]

If you set up credentials for me, I could try it from here to see if I get the same failures. Otherwise my outstanding question is about javax.mail 1.4.0 getting upgraded to 1.5.2 or 1.5.5.

[TheKorn2]

@watou happy to, how do I contact you privately outside of github?

@mrguessed for giggles in my VM, upgraded to java 8, also stripped the test rule to a single logInfo (send vince a dumb email) and sendMail . No change for either one of those.

[TheKorn2]

done!

[watou]

Well I see the same problem to the same server from here, so it's not just you! With the test JAR, it would appear to time out, getting similar stack traces to you. Then I found this stackexchange report, so I built a new mail action JAR using a completely different javax.mail implementation, and it more clearly reports a timeout:

Caused by: javax.mail.MessagingException: Exception reading response
    at com.sun.mail.smtp.SMTPTransport.readServerResponse(SMTPTransport.java:1462) ~[mail-1.4.jar:1.4]
    at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:1260) ~[mail-1.4.jar:1.4]
    at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:370) ~[mail-1.4.jar:1.4]
    at javax.mail.Service.connect(Service.java:297) ~[mail-1.4.jar:1.4]
    at javax.mail.Service.connect(Service.java:156) ~[mail-1.4.jar:1.4]
    at javax.mail.Service.connect(Service.java:105) ~[mail-1.4.jar:1.4]
    at javax.mail.Transport.send0(Transport.java:168) ~[mail-1.4.jar:1.4]
    at javax.mail.Transport.send(Transport.java:98) ~[mail-1.4.jar:1.4]
    at org.apache.commons.mail.Email.sendMimeMessage(Email.java:1411) ~[commons-email-1.4.jar:1.4]
    ... 33 common frames omitted
Caused by: java.net.SocketTimeoutException: Read timed out
    at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.8.0_65]
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[na:1.8.0_65]
    at java.net.SocketInputStream.read(SocketInputStream.java:170) ~[na:1.8.0_65]
    at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[na:1.8.0_65]
    at com.sun.mail.util.TraceInputStream.read(TraceInputStream.java:97) ~[mail-1.4.jar:1.4]
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) ~[na:1.8.0_65]
    at java.io.BufferedInputStream.read(BufferedInputStream.java:265) ~[na:1.8.0_65]
    at com.sun.mail.util.LineInputStream.readLine(LineInputStream.java:75) ~[mail-1.4.jar:1.4]
    at com.sun.mail.smtp.SMTPTransport.readServerResponse(SMTPTransport.java:1440) ~[mail-1.4.jar:1.4]
    ... 41 common frames omitted

So a failure happens with both theorg.apache.geronimo and com.sun.mail implementations of javax.mail, and both 1.2 and 1.4 versions of org.apache.commons.email. Any reason I should increase the timeout, or is it just a protocol issue, so there is no reply to be read?

[TheKorn2]

Well at the packet level the server is sending replies, it's just that openhab tells the server (in one split packet!) EHLO, HELO, then QUIT. So then it replies hi, hi, OK whatever GFY in a single packet back.

I guess first off the question is what's the timeout set to right now? (Is it zero or near zero?) And then just for a test I'd increase something ludicrously stupid, say 1000X the current value and see if anything falls out.

[watou]

I guess first off the question is what's the timeout set to right now?

The log suggested it was a full minute! So it seems like extending it further wouldn't help. Switching the mail parameters back to my Gmail setup showed the message went in about 4-5 seconds. I will look some more.

[watou]

The problem was that your mail servers do not perform STARTTLS, but instead need a negotiated SSL connection before performing SMTP. Please try this JAR, but first add mail:ssl=true to openhab.cfg and comment out any mail:tls=xxx line, stop and restart openHAB. The test JAR only differs from the official version in that it adds the mail:ssl parameter, and calls email.setSSL(sslOnConnect); so that SSL is negotiated first if mail:ssl=true.

If this works for you, too, I will submit a PR and update the example config files.

[TheKorn2]

Just to bring the notes here up to speed with a bunch of private emails...

I was unable to duplicate Watou's success, even going so far as using identical credentials to the same server. Upon re-testing, Watou was also unable to repeat his success, so we're kind of back to square one -- well defined problem without much of a visible solution.

[watou]

I'm leaning towards changes in conditions between openHAB and success with this server, as opposed to a problem with the test JAR and the stack below it. I saw it work several times this morning with mail:ssl=true, with mail:tls=true instead before that I saw 1-minute timeouts, after this morning's successes it now fails in under a second. I can't check the hosting company's status page because you have to login to see it. I can't say we're not shooting at a moving target, in other words.

[mrguessed]

Very old version of Geronimo library (c 1.3, ~2007), as SMTPTransport.sendHelo was restructured out in newer versions.

It's basically this issue:

• https://issues.apache.org/jira/browse/GERONIMO-3427

Which is consistent with the multiple 220 response lines I referred to earlier.

Looks like this fix went into a version of G 1.3.1:

• http://svn.apache.org/viewvc/geronimo/javamail/trunk/geronimo-javamail_1.3.1/geronimo-javamail_1.3.1_provider/src/main/java/org/apache/geronimo/javamail/transport/smtp/SMTPTransport.java?view=log

Not sure how we go about getting a newer rev (formally) though...

[watou]

It turns out the this branch works after all, with my credentials to the server in question -- but it didn't work for @TheKorn2 yesterday? It abandons org.apache.geronimo in preference to the com.sun.mail implementation. mail-1.4.7.jar could therefore replace javax.mail_1.4.0.v201005080615.jar as the bundle openHAB (1.8 and 2.0) uses for javax.mail.*. ...this would also slim down the mailcontrol binding, which imbeds the same implementation in its lib directory.

[TheKorn2]

Wait, I think I'm lost. I think for sanity sake, I should roll back my VM all the way back to initial conditions (using openJDK1.7 and the stock mail jar), then install ... ???which??? and re-test.

(The multiple 220 start is dead-on as far as describing the conditions in the field, so that definitely looks hopeful!)

[watou]

@TheKorn2: Try this JAR and set mail:ssl=true and comment out any mail:tls=xxx line, fully stop and restart openHAB, and try to sendMail.

MD5 (org.openhab.action.mail-1.9.0-SNAPSHOT.jar) = 12baae1cc52dcc14db56585642a73317