[stunnel-users] Stunnel exits with timeout

Fri Aug 19 01:05:33 CEST 2016

Peter,

I see from the archives that someone had a similar problem five years
ago - but I do not see a resolution.  Do you recall if a solution was
found then?
https://www.stunnel.org/pipermail/stunnel-users/2011-August/003185.html

Stephen
----------
Peter,

Apologies for not including the log info earlier.  No, the stunnel log
only show that it is binding the service pop3s to the static ip address
of the server on port 995.  It does not connect to port 110.
Excuse my naivety - but should the pop3 service (Gnu-pop3d) be running
on 110 at the same time as stunnel as it is not being called in the
stunnel.conf exec line?  I have tried it either way and the result is
the same.

Here is the message log which is slightly more verbose than the stunnel
log:

Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG5[ui]: stunnel
5.35 on x86_64-unknown-linux-gnu platform
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG5[ui]:
Compiled/running with OpenSSL 1.0.2h  3 May 2016
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[cron]: Cron
thread initialized
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG5[ui]:
Threading:PTHREAD Sockets:POLL,IPv6 TLS:ENGINE,FIPS,OCSP,PSK,SNI
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: errno:
(*__errno_location ())
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG5[ui]: Reading
configuration from file /etc/stunnel/stunnel.conf
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG5[ui]: UTF-8
byte order mark not detected
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG5[ui]: FIPS mode
disabled
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG6[ui]:
Compression enabled: 1 method(s)
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: Snagged
64 random bytes from /dev/urandom
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: PRNG
seeded successfully
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG6[ui]:
Initializing service [pop3s]
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG6[ui]: Loading
certificate from file: /etc/stunnel/stunnel.pem
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG6[ui]:
Certificate loaded from file: /etc/stunnel/stunnel.pem
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG6[ui]: Loading
private key from file: /etc/stunnel/stunnel.pem
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG6[ui]: Private
key loaded from file: /etc/stunnel/stunnel.pem
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: Private
key check succeeded
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: DH
initialization
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: Could not
load DH parameters from /etc/stunnel/stunnel.pem
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG6[ui]: Using
dynamic DH parameters
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: ECDH
initialization
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: ECDH
initialized with curve prime256v1
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: SSL
options: 0x03004004 (+0x03004000, -0x00000000)
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG5[ui]:
Configuration successful
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: Listening
file descriptor created (FD=7)
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: Option
SO_REUSEADDR set on accept socket
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: Service
[pop3s] (FD=7) bound to 60.59.114.106:995
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG6[cron]:
Executing cron jobs
Aug 18 11:40:30 oracle stunnel: LOG5[ui]: Compiled/running with OpenSSL
1.0.2h  3 May 2016
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG5[cron]:
Updating DH parameters
Aug 18 11:40:30 oracle stunnel: 2016.08.18 11:40:30 LOG7[ui]: Created
pid file /usr/local/var/lib/stunnel/var/run/stunnel.pid
Aug 18 11:40:30 oracle stunnel: LOG5[ui]: Threading:PTHREAD
Sockets:POLL,IPv6 TLS:ENGINE,FIPS,OCSP,PSK,SNI
Aug 18 11:40:30 oracle stunnel: LOG5[ui]: Reading configuration from
file /etc/stunnel/stunnel.conf
Aug 18 11:40:30 oracle stunnel: LOG5[ui]: UTF-8 byte order mark not
detected
Aug 18 11:40:30 oracle stunnel: LOG5[ui]: FIPS mode disabled
Aug 18 11:40:30 oracle stunnel: LOG6[ui]: Compression enabled: 1
method(s)
Aug 18 11:40:30 oracle stunnel: LOG6[ui]: Initializing service [pop3s]
Aug 18 11:40:30 oracle stunnel: LOG6[ui]: Loading certificate from
file: /etc/stunnel/stunnel.pem
Aug 18 11:40:30 oracle stunnel: LOG6[ui]: Certificate loaded from file:
/etc/stunnel/stunnel.pem
Aug 18 11:40:30 oracle stunnel: LOG6[ui]: Loading private key from
file: /etc/stunnel/stunnel.pem
Aug 18 11:40:30 oracle stunnel: LOG6[ui]: Private key loaded from file:
/etc/stunnel/stunnel.pem
Aug 18 11:40:30 oracle stunnel: LOG6[ui]: Using dynamic DH parameters
Aug 18 11:40:30 oracle stunnel: LOG5[ui]: Configuration successful
Aug 18 11:40:30 oracle stunnel: LOG6[cron]: Executing cron jobs
Aug 18 11:40:30 oracle stunnel: LOG5[cron]: Updating DH parameters
Aug 18 11:40:39 oracle stunnel: LOG5[cron]: DH parameters updated
Aug 18 11:40:39 oracle stunnel: 2016.08.18 11:40:39 LOG5[cron]: DH
parameters updated
Aug 18 11:40:39 oracle stunnel: 2016.08.18 11:40:39 LOG6[cron]: Cron
jobs completed in 9 seconds
Aug 18 11:40:39 oracle stunnel: 2016.08.18 11:40:39 LOG7[cron]: Waiting
86391 seconds
Aug 18 11:40:39 oracle stunnel: LOG6[cron]: Cron jobs completed in 9
seconds
Aug 18 11:42:00 oracle systemd: stunnel.service: Start operation timed
out. Terminating.
Aug 18 11:42:00 oracle stunnel: 2016.08.18 11:42:00 LOG7[ui]: Found 1
ready file
descriptor(s)                                                   
Aug 18 11:42:00 oracle stunnel: 2016.08.18 11:42:00 LOG7[ui]: FD=4
events=0x2001
revents=0x1                                                     
Aug 18 11:42:00 oracle stunnel: 2016.08.18 11:42:00 LOG7[ui]: FD=7
events=0x2001
revents=0x0                                                     
Aug 18 11:42:00 oracle stunnel: 2016.08.18 11:42:00 LOG7[ui]:
Dispatching signals from the signal
pipe                                           
Aug 18 11:42:00 oracle stunnel: 2016.08.18 11:42:00 LOG7[ui]:
Processing
SIGNAL_TERMINATE                                                       

Aug 18 11:42:00 oracle stunnel: 2016.08.18 11:42:00 LOG5[ui]:
Terminated                                                             

Aug 18 11:42:00 oracle stunnel: 2016.08.18 11:42:00 LOG7[ui]: Closing
service
[pop3s]                                                            
Aug 18 11:42:00 oracle stunnel: 2016.08.18 11:42:00 LOG7[ui]: Service
[pop3s] closed (FD=7)
Aug 18 11:42:00 oracle stunnel: 2016.08.18 11:42:00 LOG7[ui]: Service
[pop3s] closed
Aug 18 11:42:00 oracle stunnel: 2016.08.18 11:42:00 LOG7[ui]: removing
pid file /usr/local/var/lib/stunnel/var/run/stunnel.pid
Aug 18 11:42:00 oracle audit: SERVICE_START pid=1 uid=0 auid=4294967295
ses=4294967295 msg='unit=stunnel comm="systemd"
exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Aug 18 11:42:00 oracle systemd: Failed to start SSL tunnel for network
daemons.
Aug 18 11:42:00 oracle systemd: stunnel.service: Unit entered failed
state.
Aug 18 11:42:00 oracle systemd: stunnel.service: Failed with result
'timeout'.
Aug 18 11:42:00 oracle stunnel: LOG5[ui]: Terminated

On Thu, 2016-08-18 at 11:34 +0300, Peter Pentchev wrote:
> 
> On Wed, Aug 17, 2016 at 07:29:23PM -0400, SP wrote:
> > 
> > 
> > On Thu, 2016-08-18 at 01:04 +0300, Peter Pentchev wrote:
> > > 
> > > 
> > > On Wed, Aug 17, 2016 at 04:37:12PM -0400, SP wrote:
> > > > 
> > > > 
> > > > 
> > > > Summary of problem (configuration and log details below):
> > > > I am attempting to configure Stunnel to run a pop3s service on
> > > > our
> > > > server so that users can retrieve email securely.
> > > > Stunnel is started as a systemctl service.  If I include both
> > > > the
> > > > following in the stunnel.conf:
> > > > 
> > > > accept  = mail.myserver.net:995 
> > > > connect = localhost:110
> > > > 
> > > > then systemctl will exit immediately with:
> > > > Service [pop3s]: Each service must define two endpoints
> > > > stunnel.service: Control process exited, code=exited status=1 
> > > > Failed to start SSL tunnel for network daemons.
> > > > 
> > > > If I comment the connect to 110 then it will start and hang
> > > > then
> > > > eventually timeout:
> > > > stunnel.service: Failed with result 'timeout'.
> > > Try uncommenting the "connect" line, then commenting out the
> > > "exec"
> > > and
> > > "execargs" lines; see if this helps.  As it is, you're telling
> > > stunnel
> > > "listen on port 995, then connect to port 110 and also run a
> > > program";
> > > that's three things, and it wants you to tell it exactly two.
> > > 
> > > It's a different question why the "exec" one doesn't work
> > > though...
> > > In the current configuration, with the "connect" line commented
> > > out
> > > and
> > > the "exec" and "execargs" one uncommented, when you connect to
> > > port
> > > 995,
> > > can you see (with "pstree -l" or "ps awwfux" or something like
> > > that)
> > > stunnel starting a gnu-pop3d process?  Does the gnu-pop3d process
> > > log
> > > something somewhere?
> > Peter,
> > 
> > Thank you for your reply.  Commenting out the exec and execargs
> > does
> > dispense with the "requires two endpoints" fault.  The programs
> > still
> > times out, however with the program and systemctl exiting.
> OK, so does the stunnel log show that it is accepting your
> connection?
> Does the stunnel log show that it is connecting to port 110?
> Does the log of the program that you have listening on port 110 show
> that it is accepting stunnel's connection to it?
> 
> G'luck,
> Peter