[Dovecot] bug in openssl proxy code (1.0-test24) ?
Hi all,
If client connects to pop3 server, issues STLS command and then drops connection dovecot starts flooding syslog with this message repeated endlessly:
Jul 9 14:31:40 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9]
Best regards.
-- Andrey Panin | Linux and UNIX system administrator pazke@donpac.ru | PGP key: wwwkeys.pgp.net
On Fri, 2004-07-09 at 14:08, Andrey Panin wrote:
If client connects to pop3 server, issues STLS command and then drops connection dovecot starts flooding syslog with this message repeated endlessly:
Jul 9 14:31:40 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9]
So it seems. Before 1.0 I'll have to check all of my code that uses refcounting. That's annoyingly difficult to get right..
On 191, 07 09, 2004 at 02:46:46PM +0300, Timo Sirainen wrote:
On Fri, 2004-07-09 at 14:08, Andrey Panin wrote:
If client connects to pop3 server, issues STLS command and then drops connection dovecot starts flooding syslog with this message repeated endlessly:
Jul 9 14:31:40 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9]
So it seems. Before 1.0 I'll have to check all of my code that uses refcounting. That's annoyingly difficult to get right..
May be I don't understand something, but it looks like proxy->refcount simply can't reach zero here. Initial refcount value is 2, each call to ssl_step() callback increments it and even if ssl_proxy_destroy() called refcount is stil > 0. I'm confused :(
I inserted some debug i_warning() into ssl-proxy-openssl.c and got this trace:
Jul 9 15:44:52 smtp dovecot: Dovecot v1.0-test24 starting up Jul 9 15:44:53 smtp dovecot: pop3-login: ssl_proxy_init: entered Jul 9 15:44:53 smtp dovecot: pop3-login: ssl_proxy_init: finished Jul 9 15:44:53 smtp dovecot: pop3-login: ssl_proxy_init: entered Jul 9 15:44:53 smtp dovecot: pop3-login: ssl_proxy_init: finished Jul 9 15:44:53 smtp dovecot: pop3-login: ssl_proxy_init: entered Jul 9 15:44:53 smtp dovecot: pop3-login: ssl_proxy_init: finished Jul 9 15:45:01 smtp dovecot: pop3-login: ssl_proxy_init: entered Jul 9 15:45:01 smtp dovecot: pop3-login: ssl_proxy_init: finished Jul 9 15:45:03 smtp dovecot: pop3-login: ssl_proxy_new: entered Jul 9 15:45:03 smtp dovecot: pop3-login: ssl_handshake: entered Jul 9 15:45:03 smtp dovecot: pop3-login: ssl_handle_error: entered Jul 9 15:45:03 smtp dovecot: pop3-login: ssl_set_io: entered: proxy = 0x8076218 Jul 9 15:45:03 smtp dovecot: pop3-login: ssl_set_io: action = 0 SSL_ADD_INPUT Jul 9 15:45:03 smtp dovecot: pop3-login: ssl_set_io: finished Jul 9 15:45:03 smtp dovecot: pop3-login: ssl_handle_error: finished Jul 9 15:45:03 smtp dovecot: pop3-login: ssl_handshake: finished Jul 9 15:45:12 smtp dovecot: pop3-login: ssl_step: entered Jul 9 15:45:12 smtp dovecot: pop3-login: ssl_handshake: entered Jul 9 15:45:12 smtp dovecot: pop3-login: ssl_handle_error: entered Jul 9 15:45:12 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9] Jul 9 15:45:12 smtp dovecot: pop3-login: ssl_proxy_destroy: entered Jul 9 15:45:12 smtp dovecot: pop3-login: ssl_proxy_unref: entered Jul 9 15:45:12 smtp dovecot: pop3-login: ssl_proxy_destroy: finished Jul 9 15:45:12 smtp dovecot: pop3-login: ssl_handle_error: finished Jul 9 15:45:12 smtp dovecot: pop3-login: ssl_handshake: finished Jul 9 15:45:12 smtp dovecot: pop3-login: ssl_proxy_unref: entered Jul 9 15:45:12 smtp dovecot: pop3-login: ssl_step: finished Jul 9 15:45:12 smtp dovecot: pop3-login: Sending log messages too fast, throttling.. Jul 9 15:45:14 smtp dovecot: pop3-login: ssl_step: entered Jul 9 15:45:14 smtp dovecot: pop3-login: ssl_handshake: entered Jul 9 15:45:14 smtp dovecot: pop3-login: ssl_handle_error: entered Jul 9 15:45:14 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9] Jul 9 15:45:14 smtp dovecot: pop3-login: ssl_proxy_destroy: entered Jul 9 15:45:14 smtp dovecot: pop3-login: ssl_proxy_destroy: finished Jul 9 15:45:14 smtp dovecot: pop3-login: ssl_handle_error: finished Jul 9 15:45:14 smtp dovecot: pop3-login: ssl_handshake: finished Jul 9 15:45:14 smtp dovecot: pop3-login: ssl_proxy_unref: entered Jul 9 15:45:14 smtp dovecot: pop3-login: ssl_step: finished Jul 9 15:45:14 smtp dovecot: pop3-login: ssl_step: entered Jul 9 15:45:15 smtp dovecot: pop3-login: ssl_handshake: entered Jul 9 15:45:15 smtp dovecot: pop3-login: ssl_handle_error: entered Jul 9 15:45:15 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9] Jul 9 15:45:15 smtp dovecot: pop3-login: ssl_proxy_destroy: entered Jul 9 15:45:15 smtp dovecot: pop3-login: ssl_proxy_destroy: finished Jul 9 15:45:15 smtp dovecot: pop3-login: ssl_handle_error: finished Jul 9 15:45:15 smtp dovecot: pop3-login: ssl_handshake: finished Jul 9 15:45:15 smtp dovecot: pop3-login: ssl_proxy_unref: entered Jul 9 15:45:15 smtp dovecot: pop3-login: ssl_step: finished Jul 9 15:45:15 smtp dovecot: pop3-login: ssl_step: entered Jul 9 15:45:15 smtp dovecot: pop3-login: ssl_handshake: entered Jul 9 15:45:16 smtp dovecot: pop3-login: ssl_handle_error: entered Jul 9 15:45:16 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9] Jul 9 15:45:16 smtp dovecot: pop3-login: ssl_proxy_destroy: entered Jul 9 15:45:16 smtp dovecot: pop3-login: ssl_proxy_destroy: finished Jul 9 15:45:16 smtp dovecot: pop3-login: ssl_handle_error: finished Jul 9 15:45:16 smtp dovecot: pop3-login: ssl_handshake: finished Jul 9 15:45:16 smtp dovecot: pop3-login: ssl_proxy_unref: entered Jul 9 15:45:16 smtp dovecot: pop3-login: ssl_step: finished Jul 9 15:45:16 smtp dovecot: pop3-login: ssl_step: entered Jul 9 15:45:16 smtp dovecot: pop3-login: ssl_handshake: entered Jul 9 15:45:16 smtp dovecot: pop3-login: ssl_handle_error: entered Jul 9 15:45:17 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9] Jul 9 15:45:17 smtp dovecot: pop3-login: ssl_proxy_destroy: entered Jul 9 15:45:17 smtp dovecot: pop3-login: ssl_proxy_destroy: finished Jul 9 15:45:17 smtp dovecot: pop3-login: ssl_handle_error: finished Jul 9 15:45:17 smtp dovecot: pop3-login: ssl_handshake: finished Jul 9 15:45:17 smtp dovecot: pop3-login: ssl_proxy_unref: entered Jul 9 15:45:17 smtp dovecot: pop3-login: ssl_step: finished Jul 9 15:45:17 smtp dovecot: pop3-login: ssl_step: entered Jul 9 15:45:17 smtp dovecot: pop3-login: ssl_handshake: entered Jul 9 15:45:17 smtp dovecot: pop3-login: ssl_handle_error: entered Jul 9 15:45:17 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9] Jul 9 15:45:18 smtp dovecot: pop3-login: ssl_proxy_destroy: entered Jul 9 15:45:18 smtp dovecot: pop3-login: ssl_proxy_destroy: finished Jul 9 15:45:18 smtp dovecot: pop3-login: ssl_handle_error: finished Jul 9 15:45:18 smtp dovecot: pop3-login: ssl_handshake: finished Jul 9 15:45:18 smtp dovecot: pop3-login: ssl_proxy_unref: entered Jul 9 15:45:18 smtp dovecot: pop3-login: ssl_step: finished Jul 9 15:45:18 smtp dovecot: pop3-login: ssl_step: entered Jul 9 15:45:18 smtp dovecot: pop3-login: ssl_handshake: entered Jul 9 15:45:18 smtp dovecot: pop3-login: ssl_handle_error: entered Jul 9 15:45:18 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9] Jul 9 15:45:18 smtp dovecot: pop3-login: ssl_proxy_destroy: entered Jul 9 15:45:19 smtp dovecot: pop3-login: ssl_proxy_destroy: finished Jul 9 15:45:19 smtp dovecot: pop3-login: ssl_handle_error: finished Jul 9 15:45:19 smtp dovecot: pop3-login: ssl_handshake: finished Jul 9 15:45:19 smtp dovecot: pop3-login: ssl_proxy_unref: entered Jul 9 15:45:19 smtp dovecot: pop3-login: ssl_step: finished Jul 9 15:45:19 smtp dovecot: pop3-login: ssl_step: entered Jul 9 15:45:19 smtp dovecot: pop3-login: ssl_handshake: entered Jul 9 15:45:19 smtp dovecot: pop3-login: ssl_handle_error: entered Jul 9 15:45:19 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9] Jul 9 15:45:19 smtp dovecot: pop3-login: ssl_proxy_destroy: entered Jul 9 15:45:19 smtp dovecot: pop3-login: ssl_proxy_destroy: finished Jul 9 15:45:20 smtp dovecot: Killed with signal 15
Hope it will help.
-- Andrey Panin | Linux and UNIX system administrator pazke@donpac.ru | PGP key: wwwkeys.pgp.net
On Fri, 2004-07-09 at 15:05, Andrey Panin wrote:
On 191, 07 09, 2004 at 02:46:46PM +0300, Timo Sirainen wrote:
On Fri, 2004-07-09 at 14:08, Andrey Panin wrote:
If client connects to pop3 server, issues STLS command and then drops connection dovecot starts flooding syslog with this message repeated endlessly:
Jul 9 14:31:40 smtp dovecot: pop3-login: SSL_accept() syscall failed: EOF [80.254.111.9]
So it seems. Before 1.0 I'll have to check all of my code that uses refcounting. That's annoyingly difficult to get right..
May be I don't understand something, but it looks like proxy->refcount simply can't reach zero here. Initial refcount value is 2, each call to ssl_step() callback increments it and even if ssl_proxy_destroy() called refcount is stil > 0. I'm confused :(
Yes, it didn't get to zero always. ssl_step() increased it but also decreased it. It dropped from 2 -> 1 when connection was closed, and 1 -> 0 in ssl_proxy_free() which pop3-login code called. Or at least it should have worked that way. Fixed in CVS: http://dovecot.org/list/dovecot-cvs/2004-July/002902.html
participants (2)
-
Andrey Panin
-
Timo Sirainen