[stunnel-users] Stunnel exits with timeout
SP
scp.stjohn at gmail.com
Fri Aug 19 04:36:20 CEST 2016
Finally, I have stunnel working in daemon mode.
I first managed to get it running as inetd but still could not run it
as daemon until I realized that foreground was enabled in the config.
After commenting that out it runs as a daemon called by systemctl.
The main steps I took to remedy the problem were:
1. Comment out exec and execargs as you suggested. (Thank you.)
2. Add the missing DH parameters to the pem file by running
dd if=/dev/urandom count=2 | openssl dhparam -rand - 512
then appending the result to the end of the pem.
3. Commenting out "transparent"
4. commenting out "foreground" so it runs in the background as a daemon
Here is my working stunnel.conf:
--------------------------
setuid = nobody
setgid = nobody
pid = /usr/local/var/lib/stunnel/var/run/stunnel.pid
;foreground = yes
;debug = info
debug = 7
sslVersion = TLSv1.2
output = /usr/local/var/lib/stunnel/var/log/stunnel.log
;ciphers = HIGH:MEDIUM:+DH:!SSLv2:!aNULL:+SHA256:+SHA1:+MD5
ciphers = HIGH:+3DES:+DH:!aNULL:!SSLv2
RNDbytes = 64
RNDfile = /dev/urandom
RNDoverwrite = yes
delay = no
fips = no
compression = deflate
client = no
[pop3s]
accept = mail.myserver.net:995
connect = 110
cert = /etc/stunnel/stunnel.pem
key = /etc/stunnel/stunnel.pem
On Thu, 2016-08-18 at 19:05 -0400, SP wrote:
>
> 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.ht
> ml
>
> 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
More information about the stunnel-users
mailing list