Failing to send email in v1.2.2 and v1.2.1 but ok in v1.2.0, v1.1.1 and v1.0.0

[Aerius42]

Hello,

When I try to send a registration email, I received the following error statement in the log for the versions 1.2.2 and 1.2.1:

2019-01-04 15:23:58.272  INFO [nio-8090-exec-1]  i.k.m.t.c.email.EmailSmtpConnector : Sending invite to address@domain.com via SMTP using 104.199.96.85:25
2019-01-04 15:23:58.302  INFO [nio-8090-exec-1]  i.k.m.t.c.email.EmailSmtpConnector : Connecting to 104.199.96.85:25
2019-01-04 15:23:58.452 ERROR [nio-8090-exec-1]     i.k.m.c.DefaultExceptionHandler : Unknown error when handling http://domain.com/_matrix/identity/api/v1/validate/email/requestToken
java.lang.RuntimeException: Unable to send e-mail invite to address@domain.com
        at io.kamax.mxisd.threepid.connector.email.EmailSmtpConnector.send(EmailSmtpConnector.java:114) ~[classes!/:na]
        at io.kamax.mxisd.threepid.notification.email.EmailRawNotificationHandler.send(EmailRawNotificationHandler.java:65) ~[classes!/:na]
        at io.kamax.mxisd.threepid.notification.email.EmailRawNotificationHandler.send(EmailRawNotificationHandler.java:32) ~[classes!/:na]
        at io.kamax.mxisd.threepid.notification.GenericNotificationHandler.sendForValidation(GenericNotificationHandler.java:70) ~[classes!/:na]
        at io.kamax.mxisd.notification.NotificationManager.sendForValidation(NotificationManager.java:81) ~[classes!/:na]
        at io.kamax.mxisd.session.SessionMananger.create(SessionMananger.java:165) ~[classes!/:na]
        at io.kamax.mxisd.controller.identity.v1.SessionRestController.init(SessionRestController.java:97) ~[classes!/:na]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_131]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_131]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_131]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_131]
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) ~[spring-web-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133) ~[spring-web-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97) ~[spring-webmvc-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) ~[spring-webmvc-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) ~[spring-webmvc-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) ~[spring-webmvc-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963) ~[spring-webmvc-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) ~[spring-webmvc-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) [spring-webmvc-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872) [spring-webmvc-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:661) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) [spring-webmvc-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat-embed-websocket-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) [spring-web-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring
-web-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:105) [spring-web-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81) [spring-web-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) [spring-web-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:799) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:861) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_131]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_131]
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
        at java.lang.Thread.run(Thread.java:748) [na:1.8.0_131]
Caused by: javax.mail.SendFailedException: Invalid Addresses
        at com.sun.mail.smtp.SMTPTransport.rcptTo(SMTPTransport.java:2079) ~[javax.mail-1.6.2.jar!/:1.6.2]
        at com.sun.mail.smtp.SMTPTransport.sendMessage(SMTPTransport.java:1301) ~[javax.mail-1.6.2.jar!/:1.6.2]
        at io.kamax.mxisd.threepid.connector.email.EmailSmtpConnector.send(EmailSmtpConnector.java:108) ~[classes!/:na]
        ... 60 common frames omitted
Caused by: com.sun.mail.smtp.SMTPAddressFailedException: 454 4.7.1 <address@domain.com>: Relay access denied
        at com.sun.mail.smtp.SMTPTransport.rcptTo(SMTPTransport.java:1979) ~[javax.mail-1.6.2.jar!/:1.6.2]
        ... 62 common frames omitted
2019-01-04 15:23:58.456  INFO [nio-8090-exec-1]     i.k.m.c.DefaultExceptionHandler : Request POST http://domain.com/_matrix/identity/api/v1/validate/email/requestToken - Error M_UNKNOWN: Unable to send e-mail invite to address@domain.com

But with the versions 1.2.0, 1.1.1 and 1.0.0, everything goes fine:

2019-01-04 16:02:07.680  INFO [nio-8090-exec-1] enericTemplateNotificationGenerator : Generating notification content for 3PID Session validation
2019-01-04 16:02:07.750  INFO [nio-8090-exec-1]  i.k.m.t.c.email.EmailSmtpConnector : Sending invite to address@domain.com via SMTP using 104.199.96.85:587
2019-01-04 16:02:07.776  INFO [nio-8090-exec-1]  i.k.m.t.c.email.EmailSmtpConnector : Connecting to 104.199.96.85:587
2019-01-04 16:02:08.304  INFO [nio-8090-exec-1]  i.k.m.t.c.email.EmailSmtpConnector : Invite to address@domain.com was sent

I'm currently using the docker container version of MXISD and Synapse:

• Docker version 18.09.0, build 4d60db4
• avhost/docker-matrix:v0.34.0
• kamax/mxisd:1.2.0

I'm also using Mailjet as SMTP server with TLS but without TLS, I have the same results.
I tried also to replace the host name by its IP address, same result.

My mxisd.yaml config:

[...]
threepid.medium.email:
  identity:
    from: 'noreply@domain.com'
    name: 'Name Id Server'
  connectors:
    smtp:
      host: 'in-v3.mailjet.com'
      port: 587
      tls: 1 # 0 = no STARTLS, 1 = try, 2 = force
      login: 'login'
      password: 'password'
[...]

That's really weird, seems to be a bug.
Thank you for your work and your help !

[maxidorius]

@Aerius42 Thank you for reporting the issue. This is indeed a bug; regression introduced when trying to fix #100.

We believe we fixed your issue. Could you please try with image kamax/mxisd:1.2.2-1-gdf44428 using your regular SMTP config please?

If it works, it is safe for you to keep using that docker image in production.

[Aerius42]

@maxidor Thank you for your reactivity. With kamax/mxisd:1.2.2-1-gdf44428 everything seems to be ok so far. Thank you a lot !

Do you know if it is possible to force mxisd to send a test email ?

[maxidorius]

With kamax/mxisd:1.2.2-1-gdf44428 everything seems to be ok so far. Thank you a lot !

@Aerius42 Very happy to hear!

Do you know if it is possible to force mxisd to send a test email ?

No such capability at this time, sorry

[nunoperalta]

I see this is included in v1.3.0, but I'm getting the same problem. Emails are failing for the same reason.

I installed mxisd today, so I have no idea if it was working before :)

I installed using this JAR, on CentOS 7:
https://github.com/kamax-matrix/mxisd/releases/download/v1.3.0/mxisd.jar

Feb 13 00:26:54 myhost mxisd: [XNIO-1 task-4] INFO io.kamax.mxisd.session.SessionManager - Session 1550017614236 for io.kamax.matrix.ThreePid@80be73ef: sending validation notification
Feb 13 00:26:54 myhost mxisd: [XNIO-1 task-4] INFO io.kamax.mxisd.threepid.generator.GenericTemplateNotificationGenerator - Generating notification content for 3PID Session validation
Feb 13 00:26:54 myhost mxisd: [XNIO-1 task-4] INFO io.kamax.mxisd.threepid.connector.email.EmailSmtpConnector - Sending invite to myemail@example.com via SMTP using myhost.example.com:465
Feb 13 00:26:54 myhost mxisd: [XNIO-1 task-4] INFO io.kamax.mxisd.threepid.connector.email.EmailSmtpConnector - Connecting to myhost.example.com:465
Feb 13 00:26:54 myhost mxisd: [XNIO-1 task-4] INFO io.kamax.mxisd.threepid.connector.email.EmailSmtpConnector - Using SMTP authentication
Feb 13 00:29:39 myhost mxisd: [XNIO-1 task-4] ERROR io.kamax.mxisd.http.undertow.handler.SaneHandler - Unknown error when handling http://matrix.example.com/_matrix/identity/api/v1/validate/email/requestToken
Feb 13 00:29:39 myhost mxisd: java.lang.RuntimeException: Unable to send e-mail invite to myemail@example.com
Feb 13 00:29:39 myhost mxisd: at io.kamax.mxisd.threepid.connector.email.EmailSmtpConnector.send(EmailSmtpConnector.java:122)
Feb 13 00:29:39 myhost mxisd: at io.kamax.mxisd.threepid.notification.email.EmailRawNotificationHandler.send(EmailRawNotificationHandler.java:64)
Feb 13 00:29:39 myhost mxisd: at io.kamax.mxisd.threepid.notification.email.EmailRawNotificationHandler.send(EmailRawNotificationHandler.java:31)
Feb 13 00:29:39 myhost mxisd: at io.kamax.mxisd.threepid.notification.GenericNotificationHandler.sendForValidation(GenericNotificationHandler.java:72)
Feb 13 00:29:39 myhost mxisd: at io.kamax.mxisd.notification.NotificationManager.sendForValidation(NotificationManager.java:78)
Feb 13 00:29:39 myhost mxisd: at io.kamax.mxisd.session.SessionManager.create(SessionManager.java:134)
Feb 13 00:29:39 myhost mxisd: at io.kamax.mxisd.http.undertow.handler.identity.v1.SessionStartHandler.handleRequest(SessionStartHandler.java:58)
Feb 13 00:29:39 myhost mxisd: at io.kamax.mxisd.http.undertow.handler.SaneHandler.handleRequest(SaneHandler.java:65)
Feb 13 00:29:39 myhost mxisd: at io.undertow.server.Connectors.executeRootHandler(Connectors.java:360)
Feb 13 00:29:39 myhost mxisd: at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
Feb 13 00:29:39 myhost mxisd: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Feb 13 00:29:39 myhost mxisd: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Feb 13 00:29:39 myhost mxisd: at java.lang.Thread.run(Thread.java:748)
Feb 13 00:29:39 myhost mxisd: Caused by: javax.mail.MessagingException: Could not connect to SMTP host: myhost.example.com, port: 465, response: -1
Feb 13 00:29:39 myhost mxisd: at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:2197)
Feb 13 00:29:39 myhost mxisd: at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:740)
Feb 13 00:29:39 myhost mxisd: at javax.mail.Service.connect(Service.java:366)
Feb 13 00:29:39 myhost mxisd: at javax.mail.Service.connect(Service.java:246)
Feb 13 00:29:39 myhost mxisd: at javax.mail.Service.connect(Service.java:267)
Feb 13 00:29:39 myhost mxisd: at io.kamax.mxisd.threepid.connector.email.EmailSmtpConnector.send(EmailSmtpConnector.java:112)
Feb 13 00:29:39 myhost mxisd: ... 12 more
Feb 13 00:29:39 myhost mxisd: [XNIO-1 task-4] INFO io.kamax.mxisd.http.undertow.handler.BasicHttpHandler - Request POST http://matrix.example.com/_matrix/identity/api/v1/validate/email/requestToken - Error M_UNKNOWN: Unable to send e-mail invite to myemail@example.com)

[maxidorius]

Could not connect to SMTP host: myhost.example.com, port: 465, response: -1

It seems like mxisd cannot connect to your configured SMTP server, most likely because of a network restriction or because the SMTP server closed the connection on its side. So far, it doesn't look like a mxisd problem.

465 is usually used for TLS. Maybe try 587 for STARTLS with the appropriate config option?

[nunoperalta]

Port 587 worked! Thanks very much. Easy fix :)

[maxidorius]

@nunoperalta I think I've found the issue in the meantime. STARTLS is supported, but not SSL/TLS. Thank you for your report, it allowed us to discover the underlying issue! I'll open another issue to keep track of it so we can fix it for the next release.