How to debug the OMERO mail system

Hi all,

we are struggling with getting our OMERO server to send out emails properly. I believe the configuration settings for our used email server are generally fine, because it has been working few months ago for a short period of time but then stopped to work again. It is somewhat weird but I couldn’t figure out, why it stopped to work again and would love to get some hints on how I can debug the system to get more information on where the process is disturbed.

Installation overview (latest omero-server & omero-web is installed):

================================================================================
OMERO Diagnostics (admin) 5.7.1
================================================================================

Commands:   java -version                  11.0.8    (/bin/java)
Commands:   python -V                      3.6.8     (/mnt/data/OMERO.venv/server_venv3/bin/python -- 2 others)
Commands:   icegridnode --version          3.6.5     (/bin/icegridnode)
Commands:   icegridadmin --version         3.6.5     (/bin/icegridadmin)
Commands:   psql --version                 11.9      (/bin/psql)
Commands:   openssl version                1.0.2     (/bin/openssl)

Omero email configuration:

omero.ldap.user_mapping=omeName=sAMAccountName,firstName=givenName,lastName=sn,email=mail
omero.mail.auth=true
omero.mail.config=true
omero.mail.from=emailaccount@our-domain.de
omero.mail.host=mail.our-domain.de
omero.mail.password=********
omero.mail.port=465
omero.mail.smtp.debug=false
omero.mail.smtp.starttls.enable=false
omero.mail.transport.protocol=smtps
omero.mail.username=emailaccount

If I send out an email via OMERO admin console, it doesn’t report an error and for some reason always prints a double amount of emails to be send out (e.g. if I choose to addressees, it says “2 of 4 send out”:

Maybe this is a trivial configuration error, but I’m thankful for any hints on how to get to the core of the issue.

Cheers, Anna

Hi @ahamacher,

Since the configuration was working, I’d assume it’s not a problem with the configuration itself. (It certainly looks reasonable.) Is there anything in the Blitz-0.log regarding mail? What about if you set the debug property and retry?

I’m also having issues locally via a gmail account and here are a few things I’ve run into:

  • If you have 2-factor activated, you may need to use an apppassword.
  • Accessing via Java can sometimes trigger an “unusual warning” flag on an account which then needs to login naturally to clear the flag.

Ok, that’s just odd. :smile: But let’s deal with that once we have the other issue fixed.

~Josh

Good morning Josh,

I found a hint in the Blitz-0.log. The log output remains the same no matter if omero.mail.smtp.debug is used or not:

2020-09-14 09:26:38,676 ERROR [        omero.cmd.mail.SendEmailRequestI] (1-thread-1) Mail server connection failed; nested exception is javax.mail.MessagingException: Could not connect to SMTP host: mail.ourdomain.de, port: 465;
  nested exception is:
        javax.net.ssl.SSLHandshakeException: Received fatal alert: handshake_failure. Failed messages: javax.mail.MessagingException: Could not connect to SMTP host: mail.ourdomain.de, port: 465;
  nested exception is:
        javax.net.ssl.SSLHandshakeException: Received fatal alert: handshake_failure

The package omero-certificates is installed in the omero-server virtual environment and I re-executed “omero certificates” but it doesn’t change anything. I found the following topic pointing to mismatching protocol settings between java mail client and server, but can’t figure how to exactly check it for our installation:

https://stackoverflow.com/questions/6353849/received-fatal-alert-handshake-failure-through-sslhandshakeexception
https://dzone.com/articles/troubleshooting-javaxnetsslsslhandshakeexception-r

The same email server and account is used to send out server emails via package “ssmtp” on command line, so I know that the general connection and settings are fine. Unfortunately I’m not a java expert so and further hints are much appreciated.

Thanks, Anna

Makes sense. omero-certificates help with similar problems from OMERO clients to the OMERO.server, but here OMERO.server is the client talking to some other server :wink:

Interesting links. You can certainly try setting the mentioned properties via omero config:

javax.net.debug=ssl:handshake:verbose

and

https.protocols=TLSv1.2

for example. You can get a list of the “cipher suites” from your mail server by putting something like this in a file:

x = new java.net.URL("https://gmail.com")
y = x.openConnection()
y.connect()

and then running:

 jjs -Dhttps.protocols=TLSv1.2 -Djavax.net.debug=ssl:handshake:verbose url.js 2>&1 | grep -i "cipher suites"

~Josh

Hi Josh,

this topic is slowly getting really annoying :smiley:

I tried the jjs command with our mail server and the output in general is pretty fine and shows, that TLSv1.2 is negotiated without any issues. However, if I try to append the java command line options inside the omero config the client keeps trying to build up a TLSv1 connection, which probably fails because our mail servers don’t allow it for security reasons. Here is a more detailed example output from master.err after appending -Djavax.net.debug=ssl:handshake:verbose:

javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.948 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_AES_128_GCM_SHA256 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.949 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_AES_256_GCM_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.949 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.949 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.949 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.949 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_RSA_WITH_AES_256_GCM_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.950 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.950 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.950 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_DHE_RSA_WITH_AES_256_GCM_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.950 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_DHE_DSS_WITH_AES_256_GCM_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.950 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.951 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_RSA_WITH_AES_128_GCM_SHA256 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.951 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.951 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.951 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_DHE_RSA_WITH_AES_128_GCM_SHA256 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.951 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_DHE_DSS_WITH_AES_128_GCM_SHA256 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.952 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.952 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.953 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_RSA_WITH_AES_256_CBC_SHA256 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.953 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.953 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.953 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_DHE_RSA_WITH_AES_256_CBC_SHA256 for TLS10
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.953 CEST|HandshakeContext.java:297|Ignore unsupported cipher suite: TLS_DHE_DSS_WITH_AES_256_CBC_SHA256 for TLS10
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.957 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_AES_128_GCM_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.958 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_AES_256_GCM_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.958 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.958 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.958 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.958 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_RSA_WITH_AES_256_GCM_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.959 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.959 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.959 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_DHE_RSA_WITH_AES_256_GCM_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.959 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_DHE_DSS_WITH_AES_256_GCM_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.959 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.960 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_RSA_WITH_AES_128_GCM_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.960 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.960 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.960 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_DHE_RSA_WITH_AES_128_GCM_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.960 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_DHE_DSS_WITH_AES_128_GCM_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.961 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.961 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.961 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_RSA_WITH_AES_256_CBC_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.961 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.961 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.961 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_DHE_RSA_WITH_AES_256_CBC_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.962 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_DHE_DSS_WITH_AES_256_CBC_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.962 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.962 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.963 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_RSA_WITH_AES_128_CBC_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.963 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.963 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.963 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_DHE_RSA_WITH_AES_128_CBC_SHA256
javax.net.ssl|ALL|16|pool-1-thread-1|2020-09-22 10:48:48.963 CEST|HandshakeContext.java:348|Ignore unsupported cipher suite: TLS_DHE_DSS_WITH_AES_128_CBC_SHA256
javax.net.ssl|INFO|16|pool-1-thread-1|2020-09-22 10:48:48.992 CEST|AlpnExtension.java:161|No available application protocols
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.993 CEST|SSLExtensions.java:260|Ignore, context unavailable extension: application_layer_protocol_negotiation
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.993 CEST|SSLExtensions.java:260|Ignore, context unavailable extension: renegotiation_info
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.997 CEST|ClientHello.java:653|Produced ClientHello handshake message (
"ClientHello": {
  "client version"      : "TLSv1",
  "random"              : "B9 10 85 75 94 73 86 17 36 CD 4B 1C 92 D5 46 E4 30 B2 2F 88 78 88 EA 86 C8 E4 0B 39 05 A9 5E 3E",
  "session id"          : "",
  "cipher suites"       : "[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA(0xC00A), TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA(0xC014), TLS_RSA_WITH_AES_256_CBC_SHA(0x0035), TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA(0xC005), TLS_ECDH_RSA_WITH_AES_256_CBC_SHA(0xC00F), TLS_DHE_RSA_WITH_AES_256_CBC_SHA(0x0039), TLS_DHE_DSS_WITH_AES_256_CBC_SHA(0x0038), TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA(0xC009), TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA(0xC013), TLS_RSA_WITH_AES_128_CBC_SHA(0x002F), TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA(0xC004), TLS_ECDH_RSA_WITH_AES_128_CBC_SHA(0xC00E), TLS_DHE_RSA_WITH_AES_128_CBC_SHA(0x0033), TLS_DHE_DSS_WITH_AES_128_CBC_SHA(0x0032), TLS_EMPTY_RENEGOTIATION_INFO_SCSV(0x00FF)]",
  "compression methods" : "00",
  "extensions"          : [
    "server_name (0)": {
      type=host_name (0), value=mail.hhu.de
    },
    "status_request (5)": {
      "certificate status type": ocsp
      "OCSP status request": {
        "responder_id": <empty>
        "request extensions": {
          <empty>
        }
      }
    },
    "supported_groups (10)": {
      "versions": [secp256r1, secp384r1, secp521r1, ffdhe2048, ffdhe3072, ffdhe4096, ffdhe6144, ffdhe8192]
    },
    "ec_point_formats (11)": {
      "formats": [uncompressed]
    },
    "status_request_v2 (17)": {
      "cert status request": {
        "certificate status type": ocsp_multi
        "OCSP status request": {
          "responder_id": <empty>
          "request extensions": {
            <empty>
          }
        }
      }
    },
    "extended_master_secret (23)": {
      <empty>
    },
    "supported_versions (43)": {
      "versions": [TLSv1]
    }
  ]
}
)
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:48.999 CEST|Alert.java:238|Received alert message (
"Alert": {
  "level"      : "fatal",
  "description": "handshake_failure"
}
)
javax.net.ssl|ERROR|16|pool-1-thread-1|2020-09-22 10:48:49.001 CEST|TransportContext.java:318|Fatal (HANDSHAKE_FAILURE): Received fatal alert: handshake_failure (
"throwable" : {
  javax.net.ssl.SSLHandshakeException: Received fatal alert: handshake_failure
        at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:131)
        at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:117)
        at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:313)
        at java.base/sun.security.ssl.Alert$AlertConsumer.consume(Alert.java:293)
        at java.base/sun.security.ssl.TransportContext.dispatch(TransportContext.java:186)
        at java.base/sun.security.ssl.SSLTransport.decode(SSLTransport.java:171)
        at java.base/sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1403)
        at java.base/sun.security.ssl.SSLSocketImpl.readHandshakeRecord(SSLSocketImpl.java:1309)
        at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:440)
        at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:411)
        at com.sun.mail.util.SocketFetcher.configureSSLSocket(SocketFetcher.java:507)
        at com.sun.mail.util.SocketFetcher.getSocket(SocketFetcher.java:238)
        at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:1900)
        at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:638)
        at javax.mail.Service.connect(Service.java:295)
        at org.springframework.mail.javamail.JavaMailSenderImpl.connectTransport(JavaMailSenderImpl.java:503)
        at org.springframework.mail.javamail.JavaMailSenderImpl.doSend(JavaMailSenderImpl.java:422)
        at org.springframework.mail.javamail.JavaMailSenderImpl.send(JavaMailSenderImpl.java:346)
        at org.springframework.mail.javamail.JavaMailSenderImpl.send(JavaMailSenderImpl.java:363)
        at org.springframework.mail.javamail.JavaMailSenderImpl.send(JavaMailSenderImpl.java:351)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
        at com.sun.proxy.$Proxy70.send(Unknown Source)
        at ome.services.mail.MailUtil.sendEmail(MailUtil.java:100)
        at omero.cmd.mail.SendEmailRequestI.step(SendEmailRequestI.java:131)
        at omero.cmd.HandleI.steps(HandleI.java:448)
        at omero.cmd.HandleI$RunSteps.innerWork(HandleI.java:509)
        at omero.cmd.HandleI$1.doWork(HandleI.java:375)
        at omero.cmd.HandleI$1.doWork(HandleI.java:372)
        at jdk.internal.reflect.GeneratedMethodAccessor293.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
        at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:568)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at ome.security.basic.EventHandler.invoke(EventHandler.java:154)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:119)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:249)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:121)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
        at com.sun.proxy.$Proxy81.doWork(Unknown Source)
        at ome.services.util.Executor$Impl.execute(Executor.java:447)
        at omero.cmd.HandleI.run(HandleI.java:371)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at ome.services.util.Executor$Impl$1.call(Executor.java:488)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:834)}

)
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:49.002 CEST|SSLSocketImpl.java:1623|close the underlying socket
javax.net.ssl|DEBUG|16|pool-1-thread-1|2020-09-22 10:48:49.002 CEST|SSLSocketImpl.java:1642|close the SSL connection (initiative)

I tried to force the java client to use TLSv1.2 via omero config (omero.jvmcfg.append) by adding -Dhttps.protocols=TLSv1.2 and -Djdk.tls.client.protocols=TLSv1.2. I even tried -Djdk.tls.disabledAlgorithms=TLSv1 but all of these modifications didn’t show an effect on the produced debug output and the client keeps trying the TLSv1 connection.

At last I tried to disable TLSv1 and TLSv1.1 on the whole system by modifying /usr/lib/jvm/java-11-openjdk-11.0.8.10-0.el7_8.x86_64/conf/security/java.security (parameter jdk.tls.disabledAlgorithms). This however showed an effect also inside the omero log, because the connection is now not possible at all:

javax.net.ssl|ERROR|18|pool-1-thread-3|2020-09-22 10:55:19.200 CEST|TransportContext.java:318|Fatal (HANDSHAKE_FAILURE): Couldn't kickstart handshaking (
"throwable" : {
  javax.net.ssl.SSLHandshakeException: No appropriate protocol (protocol is disabled or cipher suites are inappropriate)
        at java.base/sun.security.ssl.HandshakeContext.<init>(HandshakeContext.java:171)
        at java.base/sun.security.ssl.ClientHandshakeContext.<init>(ClientHandshakeContext.java:98)
        at java.base/sun.security.ssl.TransportContext.kickstart(TransportContext.java:222)
        at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:433)
        at java.base/sun.security.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:411)
        at com.sun.mail.util.SocketFetcher.configureSSLSocket(SocketFetcher.java:507)
        at com.sun.mail.util.SocketFetcher.getSocket(SocketFetcher.java:238)
        at com.sun.mail.smtp.SMTPTransport.openServer(SMTPTransport.java:1900)
        at com.sun.mail.smtp.SMTPTransport.protocolConnect(SMTPTransport.java:638)
        at javax.mail.Service.connect(Service.java:295)
        at org.springframework.mail.javamail.JavaMailSenderImpl.connectTransport(JavaMailSenderImpl.java:503)
        at org.springframework.mail.javamail.JavaMailSenderImpl.doSend(JavaMailSenderImpl.java:422)
        at org.springframework.mail.javamail.JavaMailSenderImpl.send(JavaMailSenderImpl.java:346)
        at org.springframework.mail.javamail.JavaMailSenderImpl.send(JavaMailSenderImpl.java:363)
        at org.springframework.mail.javamail.JavaMailSenderImpl.send(JavaMailSenderImpl.java:351)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
        at com.sun.proxy.$Proxy70.send(Unknown Source)
        at ome.services.mail.MailUtil.sendEmail(MailUtil.java:100)
        at omero.cmd.mail.SendEmailRequestI.step(SendEmailRequestI.java:131)
        at omero.cmd.HandleI.steps(HandleI.java:448)
        at omero.cmd.HandleI$RunSteps.innerWork(HandleI.java:509)
        at omero.cmd.HandleI$1.doWork(HandleI.java:375)
        at omero.cmd.HandleI$1.doWork(HandleI.java:372)
        at jdk.internal.reflect.GeneratedMethodAccessor280.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
        at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:568)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at ome.security.basic.EventHandler.invoke(EventHandler.java:154)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:119)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99)
        at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:249)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:121)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
        at com.sun.proxy.$Proxy81.doWork(Unknown Source)
        at ome.services.util.Executor$Impl.execute(Executor.java:447)
        at omero.cmd.HandleI.run(HandleI.java:371)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at ome.services.util.Executor$Impl$1.call(Executor.java:488)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:834)}

)
javax.net.ssl|DEBUG|18|pool-1-thread-3|2020-09-22 10:55:19.201 CEST|SSLSocketImpl.java:1623|close the underlying socket
javax.net.ssl|DEBUG|18|pool-1-thread-3|2020-09-22 10:55:19.201 CEST|SSLSocketImpl.java:1642|close the SSL connection (initiative)

So, in the end I’m a bit lost. I understand that there is some issue in the clientside TLS protocol settings, believing that the client is currently restricted to use TLSv1 (due to first log: "supported_versions (43)": {"versions": [TLSv1]} and the kickstart failure after disabling TLSv1 systemwide) . On command line everything works fine, so I tend to think it’s an omero issue. Via omero config the java debug parameter is passed properly down to java (since the debug error logs are shown), but the other parameters mentioned here don’t show any effects. Is there another way to pass the parameters except omero.jvmcfg.append? Or do you have any other ideas how I can force the omero mailer to use TLSv1.2?

Cheers,
Anna

1 Like

Hi @ahamacher,

thanks for all the sleuthing. I have to admit, I’m also a bit lost. (Especially since this was previously working?!)

From our side, we did find one problem that we were able to correct. We will get that change released as soon as possible (< 2 weeks).

At that point we would expect the configurations in https://github.com/ome/ome-documentation/pull/2151 to definitely work. If you are interested, I’d suggest we try out this new version on your system to see if that’s the underlying issue.

If it doesn’t fix the problem, then I think we are back to low level SSL configuration to make your system work. (To your question, using omero.jvmcfg.append sounds exactly correct. :+1:)

Sorry for all the trouble.
~Josh

Hi Josh,

thanks for your feedback and effort. Since we have a separate omero test server (clone from production) I’m happy to test any configurations or code that you can provide.

It is indeed weird that it already has been working at some point, but unfortunately I can’t identify retrospectively which factor changed that broke it. If I remember right it has been working in the omero-server version 5.4.10 before upgrading to 5.5.1, but I can’t rule out that our IT department changed something on the mail servers around that time and it’s just a coincidence in the timeline. I have to admit that the transparency and communication about changes in our IT environment isn’t the best :slight_smile:

Cheers, Anna

1 Like

Thanks for the offer. If you’re comfortable temporarily replacing a jar file, you can overwrite lib/server/omero-server.jar with the contents of https://artifacts.openmicroscopy.org/artifactory/simple/ome.releases/org/openmicroscopy/omero-server/5.6.1/omero-server-5.6.1.jar and then restart your server. Otherwise, we’ll get OMERO.server 5.6.3 released and let you know.

Ok. Well, let’s not worry about that then and just try to get it working again!

All the best,
~Josh

Hi Josh,

unfortunately replacing the omero-server.jar does not work properly. The omero-server fails to start with the new jar-file with various error messages, e.g.:

2020-09-29 10:42:57,840 INFO  [                ome.services.blitz.Entry] (      main) Creating OMERO.blitz. Please wait...
2020-09-29 10:42:59,223 WARN  [                 ome.system.OmeroContext] (      main) Exception encountered during context initialization - cancelling refresh attempt: org.springframework.beans.factory.BeanDefinitionStoreException: Invalid bean definition with name 'psqlDataSourceProperties' defined in class path resource [ome/services/datalayer.xml]: Could not resolve placeholder 'omero.db.url' in value "${omero.db.url}"; nested exception is java.lang.IllegalArgumentException: Could not resolve placeholder 'omero.db.url' in value "${omero.db.url}"
2020-09-29 10:42:59,229 ERROR [                ome.services.blitz.Entry] (      main) Error on startup.
org.springframework.beans.factory.access.BootstrapException: Unable to return specified BeanFactory instance: factory key [OMERO.blitz], from group with resource name [classpath*:beanRefContext.xml]; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'OMERO.blitz' defined in URL [jar:file:/mnt/data/OMERO.server-5.6.2-ice36-b226/lib/server/omero-blitz.jar!/beanRefContext.xml]: Cannot resolve reference to bean 'ome.server' while setting constructor argument; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'ome.server' defined in URL [jar:file:/mnt/data/OMERO.server-5.6.2-ice36-b226/lib/server/omero-server.jar!/beanRefContext.xml]: Bean instantiation via constructor failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [ome.system.OmeroContext]: Constructor threw exception; nested exception is org.springframework.beans.factory.BeanDefinitionStoreException: Invalid bean definition with name 'psqlDataSourceProperties' defined in class path resource [ome/services/datalayer.xml]: Could not resolve placeholder 'omero.db.url' in value "${omero.db.url}"; nested exception is java.lang.IllegalArgumentException: Could not resolve placeholder 'omero.db.url' in value "${omero.db.url}"
        at org.springframework.beans.factory.access.SingletonBeanFactoryLocator.useBeanFactory(SingletonBeanFactoryLocator.java:404) ~[spring-beans.jar:4.3.22.RELEASE]
        at ome.system.OmeroContext.getInstance(OmeroContext.java:202) ~[omero-common.jar:5.5.6]
        at ome.services.blitz.Entry.start(Entry.java:189) ~[omero-blitz.jar:5.5.7]
        at ome.services.blitz.Entry.main(Entry.java:146) ~[omero-blitz.jar:5.5.7]
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'OMERO.blitz' defined in URL [jar:file:/mnt/data/OMERO.server-5.6.2-ice36-b226/lib/server/omero-blitz.jar!/beanRefContext.xml]: Cannot resolve reference to bean 'ome.server' while setting constructor argument; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'ome.server' defined in URL [jar:file:/mnt/data/OMERO.server-5.6.2-ice36-b226/lib/server/omero-server.jar!/beanRefContext.xml]: Bean instantiation via constructor failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [ome.system.OmeroContext]: Constructor threw exception; nested exception is org.springframework.beans.factory.BeanDefinitionStoreException: Invalid bean definition with name 'psqlDataSourceProperties' defined in class path resource [ome/services/datalayer.xml]: Could not resolve placeholder 'omero.db.url' in value "${omero.db.url}"; nested exception is java.lang.IllegalArgumentException: Could not resolve placeholder 'omero.db.url' in value "${omero.db.url}"
        at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveReference(BeanDefinitionValueResolver.java:359) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.BeanDefinitionValueResolver.resolveValueIfNecessary(BeanDefinitionValueResolver.java:108) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.ConstructorResolver.resolveConstructorArguments(ConstructorResolver.java:634) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:145) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:1198) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1100) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:511) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:481) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:312) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:308) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:202) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:1086) ~[spring-context.jar:4.3.14.RELEASE]
        at org.springframework.beans.factory.access.SingletonBeanFactoryLocator.useBeanFactory(SingletonBeanFactoryLocator.java:396) ~[spring-beans.jar:4.3.22.RELEASE]
        ... 3 common frames omitted
Caused by: org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'ome.server' defined in URL [jar:file:/mnt/data/OMERO.server-5.6.2-ice36-b226/lib/server/omero-server.jar!/beanRefContext.xml]: Bean instantiation via constructor failed; nested exception is org.springframework.beans.BeanInstantiationException: Failed to instantiate [ome.system.OmeroContext]: Constructor threw exception; nested exception is org.springframework.beans.factory.BeanDefinitionStoreException: Invalid bean definition with name 'psqlDataSourceProperties' defined in class path resource [ome/services/datalayer.xml]: Could not resolve placeholder 'omero.db.url' in value "${omero.db.url}"; nested exception is java.lang.IllegalArgumentException: Could not resolve placeholder 'omero.db.url' in value "${omero.db.url}"
        at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:279) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:1198) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1100) ~[spring-beans.jar:4.3.22.RELEASE]
        at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:511) ~[spring-beans.jar:4.3.22.RELEASE]

....

However, I’m happy to wait for the 5.6.3 release and retry it.

Cheers, Anna

Doh, apologies. There would need to be one or two more jars changed. I should have thought of that. The release should be ready very soon though. We’ll keep you posted. ~J

As at Release of OMERO.server 5.6.3 you can now give OMERO.server 5.6.3 a try, let’s hope that works better for you! https://docs.openmicroscopy.org/omero/5.6/sysadmins/mail.html may be helpful.

1 Like

Good morning Mark and Josh,

the new omero-server version works like a charm! The emails are sent out and even the curious message about the doubled email amount disappeared.

So the email problem is finally solved, yippiiee! :partying_face:

But I’ve seen one strange message, when trying to reset the omero.jvmcfg.append parameter to its former value. When using a hyphen at the beginning of the parameter value I’m getting this message:

(server_venv3) [omero-server@omero-cai-test data]$ omero config set omero.jvmcfg.append '-Dcom.sun.jndi.ldap.connect.pool.timeout=500'
usage: /mnt/data/OMERO.venv/server_venv3/bin/omero config set
       [-h] [--report] [-f FILE] KEY [VALUE]
/mnt/data/OMERO.venv/server_venv3/bin/omero config set: error: unrecognized arguments: -Dcom.sun.jndi.ldap.connect.pool.timeout=500

(server_venv3) [omero-server@omero-cai-test data]$ omero config get
omero.jvmcfg.append=-Djavax.net.debug=ssl:handshake:verbose -Dcom.sun.jndi.ldap.connect.pool.timeout=500 -Dhttps.protocols=TLSv1.2 -Djdk.tls.client.protocols=TLSv1.2

This has been working until now. If I put space before the hyphen it works and will hopefully also work for java, but I was wondering if this change was intended or not.

(server_venv3) [omero-server@omero-cai-test data]$ omero config set omero.jvmcfg.append ' -Dcom.sun.jndi.ldap.connect.pool.timeout=500'

(server_venv3) [omero-server@omero-cai-test data]$ omero config get
omero.jvmcfg.append= -Dcom.sun.jndi.ldap.connect.pool.timeout=500

Thanks a lot for your work on this topic!
Anna

I’m surprised it worked before, to be honest! I’ve always used lines like,

omero config set -- omero.jvmcfg.append -Xverify:none

Options coming after that -- should inhibit the argument parsing, as with grep, etc.

1 Like

Thanks Mark for the hint! Works perfectly :slight_smile: