[stunnel-users] Scan to email failure: RapbianPi3 to Office365

Hi.

I recently bought a Pi3 and have loaded Raspbian with Doobs (Previously I had this running faultlessly under a Windows Server for my Canon multi function printer that does not support SSL/TLS but only authentication). After about 8 attempts to get Stunnel4 working (there doesn't seem to be a later version to install via the command line) I eventually found that Stunnel4 works fine as long as one doesn't update Dabian from the initial Doobs install. So, I now have the service running and listening on port 25 with the following config file:

debug=7 output=/etc/stunnel/stunnel.log client=yes options=NO_SSLv2 (I added this last night after reading a blog)

[SMTP OUT] sslVersion=TLSv1 (I added this last night after reading a blog) protocol=smtp accept=25 connect=smtp.office365.com:587

On restarting the service I see the following which looks okay to my untrained eye:

2017.04.03 09:42:09 LOG7[3570]: Dispatching signals from the signal pipe 2017.04.03 09:42:09 LOG7[3570]: Processing SIGNAL_TERMINATE 2017.04.03 09:42:09 LOG5[3570]: Terminated 2017.04.03 09:42:09 LOG7[3570]: Closing service [SMTP OUT] 2017.04.03 09:42:09 LOG7[3570]: Service [SMTP OUT] closed (FD=7) 2017.04.03 09:42:09 LOG7[3570]: Service [SMTP OUT] closed 2017.04.03 09:42:09 LOG7[3570]: removing pid file /var/run/stunnel4.pid 2017.04.03 09:42:09 LOG7[3926]: Clients allowed=500 2017.04.03 09:42:09 LOG5[3926]: stunnel 5.06 on arm-unknown-linux-gnueabihf platform 2017.04.03 09:42:09 LOG5[3926]: Compiled with OpenSSL 1.0.1k 8 Jan 2015 2017.04.03 09:42:09 LOG5[3926]: Running with OpenSSL 1.0.1t 3 May 2016 2017.04.03 09:42:09 LOG5[3926]: Update OpenSSL shared libraries or rebuild stunnel 2017.04.03 09:42:09 LOG5[3926]: Threading:PTHREAD Sockets:POLL,IPv6,SYSTEMD SSL:ENGINE,OCSP,FIPS Auth:LIB$ 2017.04.03 09:42:09 LOG7[3926]: errno: (*__errno_location ()) 2017.04.03 09:42:09 LOG5[3926]: Reading configuration from file /etc/stunnel/stunnel4.conf 2017.04.03 09:42:09 LOG5[3926]: FIPS mode disabled 2017.04.03 09:42:09 LOG7[3926]: Compression disabled 2017.04.03 09:42:09 LOG7[3926]: Snagged 64 random bytes from /dev/urandom 2017.04.03 09:42:09 LOG7[3926]: PRNG seeded successfully 2017.04.03 09:42:09 LOG6[3926]: Initializing service [SMTP OUT] 2017.04.03 09:42:09 LOG7[3926]: No private key specified 2017.04.03 09:42:09 LOG7[3926]: SSL options: 0x03000004 (+0x03000000, -0x00000000) 2017.04.03 09:42:09 LOG5[3926]: Configuration successful 2017.04.03 09:42:09 LOG7[3926]: Listening file descriptor created (FD=7) 2017.04.03 09:42:09 LOG7[3926]: Service [SMTP OUT] (FD=7) bound to 0.0.0.0:25 2017.04.03 09:42:09 LOG7[3927]: Created pid file /var/run/stunnel4.pid

When sending a scan from the printer to an email address I see the following in the log file:

2017.04.03 10:00:05 LOG7[3927]: Service [SMTP OUT] accepted (FD=3) from 192.168.8.99:1085 2017.04.03 10:00:05 LOG7[3960]: Service [SMTP OUT] started 2017.04.03 10:00:05 LOG5[3960]: Service [SMTP OUT] accepted connection from 192.168.8.99:1085 2017.04.03 10:00:05 LOG6[3960]: s_connect: connecting 40.101.73.162:587 2017.04.03 10:00:05 LOG7[3960]: s_connect: s_poll_wait 40.101.73.162:587: waiting 10 seconds 2017.04.03 10:00:05 LOG5[3960]: s_connect: connected 40.101.73.162:587 2017.04.03 10:00:05 LOG5[3960]: Service [SMTP OUT] connected remote server from 192.168.8.33:59792 2017.04.03 10:00:05 LOG7[3960]: Remote socket (FD=9) initialized 2017.04.03 10:00:05 LOG7[3960]: <- 220 DB6PR07CA0179.outlook.office365.com Microsoft ESMTP MAIL Service $ 2017.04.03 10:00:05 LOG7[3960]: -> 220 DB6PR07CA0179.outlook.office365.com Microsoft ESMTP MAIL Service $ 2017.04.03 10:00:05 LOG7[3960]: -> EHLO localhost 2017.04.03 10:00:05 LOG7[3960]: <- 250-DB6PR07CA0179.outlook.office365.com Hello [46.208.253.189] 2017.04.03 10:00:05 LOG7[3960]: <- 250-SIZE 157286400 2017.04.03 10:00:05 LOG7[3960]: <- 250-PIPELINING 2017.04.03 10:00:05 LOG7[3960]: <- 250-DSN 2017.04.03 10:00:05 LOG7[3960]: <- 250-ENHANCEDSTATUSCODES 2017.04.03 10:00:05 LOG7[3960]: <- 250-STARTTLS 2017.04.03 10:00:05 LOG7[3960]: <- 250-8BITMIME 2017.04.03 10:00:05 LOG7[3960]: <- 250-BINARYMIME 2017.04.03 10:00:05 LOG7[3960]: <- 250-CHUNKING 2017.04.03 10:00:05 LOG7[3960]: <- 250 SMTPUTF8 2017.04.03 10:00:05 LOG7[3960]: -> STARTTLS 2017.04.03 10:00:05 LOG7[3960]: <- 220 2.0.0 SMTP server ready 2017.04.03 10:00:05 LOG6[3960]: SNI: sending servername: outlook.office365.com 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): before/connect initialization 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: SSL state (connect): unknown state 2017.04.03 10:00:05 LOG7[3960]: 0 items in the session cache 2017.04.03 10:00:05 LOG7[3960]: 2 client connects (SSL_connect()) 2017.04.03 10:00:05 LOG7[3960]: 2 client connects that finished 2017.04.03 10:00:05 LOG7[3960]: 0 client renegotiations requested 2017.04.03 10:00:05 LOG7[3960]: 0 server connects (SSL_accept()) 2017.04.03 10:00:05 LOG7[3960]: 0 server connects that finished 2017.04.03 10:00:05 LOG7[3960]: 0 server renegotiations requested 2017.04.03 10:00:05 LOG7[3960]: 0 session cache hits 2017.04.03 10:00:05 LOG7[3960]: 0 external session cache hits 2017.04.03 10:00:05 LOG7[3960]: 0 session cache misses 2017.04.03 10:00:05 LOG7[3960]: 0 session cache timeouts 2017.04.03 10:00:05 LOG6[3960]: SSL connected: new session negotiated 2017.04.03 10:00:05 LOG6[3960]: Negotiated TLSv1 ciphersuite ECDHE-RSA-AES128-SHA (128-bit encryption) 2017.04.03 10:00:05 LOG6[3960]: Compression: null, expansion: null 2017.04.03 10:00:10 LOG6[3960]: SSL socket closed (SSL_read) 2017.04.03 10:00:10 LOG7[3960]: Sent socket write shutdown 2017.04.03 10:00:10 LOG5[3960]: Connection closed: 23 byte(s) sent to SSL, 79 byte(s) sent to socket 2017.04.03 10:00:10 LOG7[3960]: Remote socket (FD=9) closed 2017.04.03 10:00:10 LOG7[3960]: Local socket (FD=3) closed 2017.04.03 10:00:10 LOG7[3960]: Service [SMTP OUT] finished (0 left) 2017.04.03 10:00:20 LOG7[3927]: Service [SMTP OUT] accepted (FD=3) from 192.168.8.99:1086 2017.04.03 10:00:20 LOG7[3961]: Service [SMTP OUT] started 2017.04.03 10:00:20 LOG5[3961]: Service [SMTP OUT] accepted connection from 192.168.8.99:1086 2017.04.03 10:00:20 LOG6[3961]: s_connect: connecting 40.101.72.194:587 2017.04.03 10:00:20 LOG7[3961]: s_connect: s_poll_wait 40.101.72.194:587: waiting 10 seconds 2017.04.03 10:00:20 LOG5[3961]: s_connect: connected 40.101.72.194:587 2017.04.03 10:00:20 LOG5[3961]: Service [SMTP OUT] connected remote serve from 192.168.8.33:57422 2017.04.03 10:00:20 LOG7[3961]: Remote socket (FD=9) initialized 2017.04.03 10:00:21 LOG7[3961]: <- 220 DB6PR07CA0014.outlook.office365.com Microsoft ESMTP MAIL Service $ 2017.04.03 10:00:21 LOG7[3961]: -> 220 DB6PR07CA0014.outlook.office365.com Microsoft ESMTP MAIL Service $ 2017.04.03 10:00:21 LOG7[3961]: -> EHLO localhost 2017.04.03 10:00:21 LOG7[3961]: <- 250-DB6PR07CA0014.outlook.office365.com Hello [46.208.253.189] 2017.04.03 10:00:21 LOG7[3961]: <- 250-SIZE 157286400 2017.04.03 10:00:21 LOG7[3961]: <- 250-PIPELINING 2017.04.03 10:00:21 LOG7[3961]: <- 250-DSN 2017.04.03 10:00:21 LOG7[3961]: <- 250-ENHANCEDSTATUSCODES 2017.04.03 10:00:21 LOG7[3961]: <- 250-STARTTLS 2017.04.03 10:00:21 LOG7[3961]: <- 250-8BITMIME 2017.04.03 10:00:21 LOG7[3961]: <- 250-BINARYMIME 2017.04.03 10:00:21 LOG7[3961]: <- 250-CHUNKING 2017.04.03 10:00:21 LOG7[3961]: <- 250 SMTPUTF8 2017.04.03 10:00:21 LOG7[3961]: -> STARTTLS 2017.04.03 10:00:21 LOG7[3961]: <- 220 2.0.0 SMTP server ready 2017.04.03 10:00:21 LOG6[3961]: SNI: sending servername: outlook.office365.com 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): before/connect initialization 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: SSL state (connect): unknown state 2017.04.03 10:00:21 LOG7[3961]: 0 items in the session cache 2017.04.03 10:00:21 LOG7[3961]: 3 client connects (SSL_connect()) 2017.04.03 10:00:21 LOG7[3961]: 3 client connects that finished 2017.04.03 10:00:21 LOG7[3961]: 0 client renegotiations requested 2017.04.03 10:00:21 LOG7[3961]: 0 server connects (SSL_accept()) 2017.04.03 10:00:21 LOG7[3961]: 0 server connects that finished 2017.04.03 10:00:21 LOG7[3961]: 0 server renegotiations requested 2017.04.03 10:00:21 LOG7[3961]: 0 session cache hits 2017.04.03 10:00:21 LOG7[3961]: 0 external session cache hits 2017.04.03 10:00:21 LOG7[3961]: 0 session cache misses 2017.04.03 10:00:21 LOG7[3961]: 0 session cache timeouts 2017.04.03 10:00:21 LOG6[3961]: SSL connected: new session negotiated 2017.04.03 10:00:21 LOG6[3961]: Negotiated TLSv1 ciphersuite ECDHE-RSA-AES128-SHA (128-bit encryption) 2017.04.03 10:00:21 LOG6[3961]: Compression: null, expansion: null 2017.04.03 10:00:26 LOG6[3961]: SSL socket closed (SSL_read) 2017.04.03 10:00:26 LOG7[3961]: Sent socket write shutdown 2017.04.03 10:00:26 LOG5[3961]: Connection closed: 23 byte(s) sent to SSL, 79 byte(s) sent to socket 2017.04.03 10:00:26 LOG7[3961]: Remote socket (FD=9) closed 2017.04.03 10:00:26 LOG7[3961]: Local socket (FD=3) closed 2017.04.03 10:00:26 LOG7[3961]: Service [SMTP OUT] finished (0 left)

At the end of this, no email is received. I can't tell from the above if the document is not being received by Stunnel from the printer or if Stunnel can not pass the document to Office365. It looks like TLSv1 is being negotiated and some data is being sent but then it closes the connection.

Any help would be much appreciated.

Regards,

Graeme