Strange "IMAP connection broken (server response)" errors

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
2 messages Options
Reply | Threaded
Open this post in threaded view
|

Strange "IMAP connection broken (server response)" errors

Kadlecsik József
Hello,

We upgraded one of our dovecot servers to debian stretch with dovecot
2.2.27 and since then one of our users has been experiencing random IMAP
failures.

We enabled raw logging at the server side and it shows normal IMAP
commands/responses:

1507292522.222427 * 6 FETCH (FLAGS () BODYSTRUCTURE ("text" "plain"
("charset" "us-ascii")
 NIL NIL "7bit" 4645 112 NIL NIL NIL NIL))
1507292522.222653 00000011 OK Fetch completed (0.006 + 0.000 secs).

On the client side the user runs alpine and the corresponding debug lines:

IMAP DEBUG 14:22:02.216167: 00000011 FETCH 6 (BODYSTRUCTURE FLAGS)

14:22:02.217396
IMAP 14:22:02 10/6 mm_notify bye:
{[127.0.0.1]:1555/imap/user="ha4aa"}INBOX: [CLOSED] IMAP connection broken
(server response)

14:22:02.217471
IMAP 14:22:02 10/6 mm_log error: [CLOSED] IMAP connection broken (server
response)

The "[127.0.0.1]:1555/imap/user="ha4aa" part in the log comes from an
socat inserted between the client and the server to check independetly the
imap session. According to socat, the server response didn't reach the
client!:

00000010 OK Fetch completed (0.005 + 0.000 secs).\r
> 2017/10/06 14:22:02.216299  length=40 from=845 to=884
00000011 FETCH 6 (BODYSTRUCTURE FLAGS)\r

and here ends the socat log, the server response didn't reach the client.

The same alpine package is used against older dovecot servers from debian
jessie and works flawlessly.

The server and client are both KVM guests and there's no any content
filtering software between them. There's no corresponding error in the
dovecot log file and dovecot didn't regard the connection broken and
detected client close:

...
Oct  6 14:19:44 mail2 dovecot: imap(ha4aa): Debug: Mailbox INBOX: Opened
mail UID=55244 because: MIME part
Oct  6 14:22:02 mail2 dovecot: imap(ha4aa): Connection closed in=797
out=73151

We are out of the ideas what can be the reason for the random lost server
responses.

Any help is appreciated!

Best regards,
Jozsef
--
E-mail : [hidden email]
PGP key: http://www.kfki.hu/~kadlec/pgp_public_key.txt
Address: Wigner Research Centre for Physics, Hungarian Academy of Sciences
         H-1525 Budapest 114, POB. 49, Hungary
Reply | Threaded
Open this post in threaded view
|

Re: Strange "IMAP connection broken (server response)" errors

Kadlecsik József
Hello,

On Fri, 6 Oct 2017, Jozsef Kadlecsik wrote:

> We upgraded one of our dovecot servers to debian stretch with dovecot
> 2.2.27 and since then one of our users has been experiencing random IMAP
> failures.
>
> We enabled raw logging at the server side and it shows normal IMAP
> commands/responses:
>
> 1507292522.222427 * 6 FETCH (FLAGS () BODYSTRUCTURE ("text" "plain"
> ("charset" "us-ascii")
>  NIL NIL "7bit" 4645 112 NIL NIL NIL NIL))
> 1507292522.222653 00000011 OK Fetch completed (0.006 + 0.000 secs).
>
> On the client side the user runs alpine and the corresponding debug lines:
>
> IMAP DEBUG 14:22:02.216167: 00000011 FETCH 6 (BODYSTRUCTURE FLAGS)
>
> 14:22:02.217396
> IMAP 14:22:02 10/6 mm_notify bye:
> {[127.0.0.1]:1555/imap/user="ha4aa"}INBOX: [CLOSED] IMAP connection broken
> (server response)
>
> 14:22:02.217471
> IMAP 14:22:02 10/6 mm_log error: [CLOSED] IMAP connection broken (server
> response)
>
> The "[127.0.0.1]:1555/imap/user="ha4aa" part in the log comes from an
> socat inserted between the client and the server to check independently
> the imap session. According to socat, the server response didn't reach
> the client!:
>
> 00000010 OK Fetch completed (0.005 + 0.000 secs).\r
> > 2017/10/06 14:22:02.216299  length=40 from=845 to=884
> 00000011 FETCH 6 (BODYSTRUCTURE FLAGS)\r
>
> and here ends the socat log.

The date of the last rawlog line corresponds to an ssl debug log of
dovecot (from the last run):

Oct 20 18:50:05 mail2 dovecot: imap-login: Debug: SSL error: SSL_read()
failed: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init

I added the patch "openssl: Clear error queue after an incomplete
SSL_shutdown", recompiled the package but it did not help.

Any help is highly welcomed!

Best regards,
Jozsef
--
E-mail : [hidden email]
PGP key: http://www.kfki.hu/~kadlec/pgp_public_key.txt
Address: Wigner Research Centre for Physics, Hungarian Academy of Sciences
         H-1525 Budapest 114, POB. 49, Hungary