Aerogramme IMAP hanged on 2/3 testing servers #106

New issue

Open

opened 2024-03-02 11:43:16 +00:00 by quentin · 1 comment

quentin commented

2024-03-02 11:43:16 +00:00

Owner

CPU was low (no infinite loop).
Servers were PAR and WAW.
TLS negociations seemed OK (openssl s_client -connect displayed certificate info and a CONNECTED message if I remember correctly... Not so sure anymore in fact... Let's not assume that).

WAW log:

aerogramme-1  | 2024-03-02T05:34:06.550088Z ERROR aerogramme::imap: closing errored netloop core for [::ffff:xxxx]:51975: Received malformed message
aerogramme-1  | 2024-03-02T05:34:06.550466Z  INFO aerogramme::imap: runner is quitting
aerogramme-1  | 2024-03-02T05:56:53.201776Z  INFO aerogramme::imap: IMAP: accepted connection from [::ffff:xxxx]:48052
aerogramme-1  | 2024-03-02T05:56:53.203002Z DEBUG aerogramme::imap: netloop successfully initialized addr=[::ffff:xxxx]:48052
aerogramme-1  | 2024-03-02T05:56:53.203604Z ERROR aerogramme::imap: closing errored netloop core for [::ffff:xxxx]:48052: Received malformed message
aerogramme-1  | 2024-03-02T05:56:53.204008Z DEBUG aerogramme::imap: command cmd=ImapCommand(Command { tag: Tag("A001"), body: Capability }) sock=[::ffff:xxxx]:48052
aerogramme-1  | 2024-03-02T05:56:53.204177Z DEBUG aerogramme::imap::flow: try change state state=NotAuthenticated transition=None
aerogramme-1  | 2024-03-02T05:56:53.204239Z DEBUG aerogramme::imap::flow: transition succeeded state=NotAuthenticated
aerogramme-1  | 2024-03-02T05:56:53.204282Z DEBUG aerogramme::imap: response cmd=Response(Response { body: [Data(Capability([Enable, Move, Imap4Rev1, LiteralPlus, Other(CapabilityOther(Atom("CONDSTORE"))), Unselect, Idle, Other(CapabilityOther(Atom("LIST-STATUS"))), Other(CapabilityOther(Atom("UIDPLUS")))]+))], completion: Tagged(Tagged { tag: Tag("A001"), body: StatusBody { kind: Ok, code: None, text: Text("Server capabilities") } }) }) sock=[::ffff:xxxx]:48052
aerogramme-1  | 2024-03-02T05:56:53.204434Z  INFO aerogramme::imap: runner is quitting
aerogramme-1  | 2024-03-02T06:39:50.884159Z  INFO aerogramme::imap: IMAP: accepted connection from [::ffff:xxxx]:59856
aerogramme-1  | 2024-03-02T06:39:50.885193Z DEBUG aerogramme::imap: netloop successfully initialized addr=[::ffff:xxxx]:59856
aerogramme-1  | 2024-03-02T06:39:51.142040Z ERROR aerogramme::imap: closing errored netloop core for [::ffff:xxxx]:59856: Received malformed message
aerogramme-1  | 2024-03-02T06:39:51.142515Z  INFO aerogramme::imap: runner is quitting
aerogramme-1  | 2024-03-02T10:40:11.180338Z  INFO aerogramme::auth: AUTH: accepted connection from [::1]:59594
aerogramme-1  | 2024-03-02T10:46:54.401758Z  INFO aerogramme::auth: Reading buffer empty, connection has been closed. Exiting AUTH session.
aerogramme-1  | 2024-03-02T10:46:54.402239Z  INFO aerogramme::auth: Auth session succeeded

PAR log:

aerogramme-1  | 2024-03-02T08:34:43.753986Z  INFO aerogramme::imap: IMAP: accepted connection from [::ffff:xxxx]:64896
aerogramme-1  | 2024-03-02T08:34:43.755664Z DEBUG aerogramme::imap: netloop successfully initialized addr=[::ffff:xxxx]:64896
aerogramme-1  | 2024-03-02T08:34:43.861353Z DEBUG aerogramme::imap: command cmd=ImapCommand(Command { tag: Tag("a001"), body: Capability }) sock=[::ffff:xxxx]:64896
aerogramme-1  | 2024-03-02T08:34:43.861512Z DEBUG aerogramme::imap::flow: try change state state=NotAuthenticated transition=None
aerogramme-1  | 2024-03-02T08:34:43.861547Z DEBUG aerogramme::imap::flow: transition succeeded state=NotAuthenticated
aerogramme-1  | 2024-03-02T08:34:43.861579Z DEBUG aerogramme::imap: response cmd=Response(Response { body: [Data(Capability([Imap4Rev1, Move, Enable, Idle, Other(CapabilityOther(Atom("UIDPLUS"))), Other(CapabilityOther(Atom("LIST-STATUS"))), Unselect, LiteralPlus, Other(CapabilityOther(Atom("CONDSTORE")))]+))], completion: Tagged(Tagged { tag: Tag("a001"), body: StatusBody { kind: Ok, code: None, text: Text("Server capabilities") } }) }) sock=[::ffff:xxxx]:64896
aerogramme-1  | 2024-03-02T08:34:44.116749Z ERROR aerogramme::imap: closing errored netloop core for [::ffff:xxxx]:64896: Received malformed message
aerogramme-1  | 2024-03-02T08:34:44.117115Z  INFO aerogramme::imap: runner is quitting
aerogramme-1  | 2024-03-02T09:11:48.381699Z  INFO aerogramme::auth: AUTH: accepted connection from [::1]:59434
aerogramme-1  | 2024-03-02T09:11:48.382206Z DEBUG aerogramme::auth: Made progress state=HandshakePart(Version { major: 1, minor: 0 })
aerogramme-1  | 2024-03-02T09:11:48.382347Z DEBUG aerogramme::auth: Made progress state=HandshakeDone
aerogramme-1  | 2024-03-02T09:18:30.821344Z  INFO aerogramme::auth: Reading buffer empty, connection has been closed. Exiting AUTH session.
aerogramme-1  | 2024-03-02T09:18:30.821634Z  INFO aerogramme::auth: Auth session succeeded
aerogramme-1  | 2024-03-02T09:34:01.935501Z  INFO aerogramme::auth: AUTH: accepted connection from [::1]:36072
aerogramme-1  | 2024-03-02T09:34:01.936079Z DEBUG aerogramme::auth: Made progress state=HandshakePart(Version { major: 1, minor: 0 })
aerogramme-1  | 2024-03-02T09:34:01.936165Z DEBUG aerogramme::auth: Made progress state=HandshakeDone
aerogramme-1  | 2024-03-02T09:35:42.548789Z  INFO aerogramme::auth: Reading buffer empty, connection has been closed. Exiting AUTH session.
aerogramme-1  | 2024-03-02T09:35:42.549144Z  INFO aerogramme::auth: Auth session succeeded
aerogramme-1  | 2024-03-02T11:19:49.714736Z  INFO aerogramme::imap: IMAP: accepted connection from [::ffff:xxxx]:60274
aerogramme-1  | 2024-03-02T11:19:49.715693Z DEBUG aerogramme::imap: netloop successfully initialized addr=[::ffff:xxxx]:60274
aerogramme-1  | 2024-03-02T11:19:49.716149Z ERROR aerogramme::imap: closing errored netloop core for [::ffff:xxxx]:60274: Received malformed message
aerogramme-1  | 2024-03-02T11:19:49.716658Z DEBUG aerogramme::imap: command cmd=ImapCommand(Command { tag: Tag("A001"), body: Capability }) sock=[::ffff:XXXX]:60274
aerogramme-1  | 2024-03-02T11:19:49.716849Z DEBUG aerogramme::imap::flow: try change state state=NotAuthenticated transition=None
aerogramme-1  | 2024-03-02T11:19:49.716888Z DEBUG aerogramme::imap::flow: transition succeeded state=NotAuthenticated
aerogramme-1  | 2024-03-02T11:19:49.716929Z DEBUG aerogramme::imap: response cmd=Response(Response { body: [Data(Capability([Imap4Rev1, Move, Enable, Idle, Other(CapabilityOther(Atom("UIDPLUS"))), Other(CapabilityOther(Atom("LIST-STATUS"))), Unselect, LiteralPlus, Other(CapabilityOther(Atom("CONDSTORE")))]+))], completion: Tagged(Tagged { tag: Tag("A001"), body: StatusBody { kind: Ok, code: None, text: Text("Server capabilities") } }) }) sock=[::ffff:xxxx]:60274
aerogramme-1  | 2024-03-02T11:19:49.717099Z  INFO aerogramme::imap: runner is quitting

I don't remember why but I suppose a lock issue between the Dovecot Auth protocol and the IMAP runner. Something like acquiring a RW lock and blocking the whole server.

CPU was low (no infinite loop). Servers were PAR and WAW. TLS negociations seemed OK (`openssl s_client -connect` displayed certificate info and a `CONNECTED` message if I remember correctly... Not so sure anymore in fact... Let's not assume that). WAW log: ``` aerogramme-1 | 2024-03-02T05:34:06.550088Z ERROR aerogramme::imap: closing errored netloop core for [::ffff:xxxx]:51975: Received malformed message aerogramme-1 | 2024-03-02T05:34:06.550466Z INFO aerogramme::imap: runner is quitting aerogramme-1 | 2024-03-02T05:56:53.201776Z INFO aerogramme::imap: IMAP: accepted connection from [::ffff:xxxx]:48052 aerogramme-1 | 2024-03-02T05:56:53.203002Z DEBUG aerogramme::imap: netloop successfully initialized addr=[::ffff:xxxx]:48052 aerogramme-1 | 2024-03-02T05:56:53.203604Z ERROR aerogramme::imap: closing errored netloop core for [::ffff:xxxx]:48052: Received malformed message aerogramme-1 | 2024-03-02T05:56:53.204008Z DEBUG aerogramme::imap: command cmd=ImapCommand(Command { tag: Tag("A001"), body: Capability }) sock=[::ffff:xxxx]:48052 aerogramme-1 | 2024-03-02T05:56:53.204177Z DEBUG aerogramme::imap::flow: try change state state=NotAuthenticated transition=None aerogramme-1 | 2024-03-02T05:56:53.204239Z DEBUG aerogramme::imap::flow: transition succeeded state=NotAuthenticated aerogramme-1 | 2024-03-02T05:56:53.204282Z DEBUG aerogramme::imap: response cmd=Response(Response { body: [Data(Capability([Enable, Move, Imap4Rev1, LiteralPlus, Other(CapabilityOther(Atom("CONDSTORE"))), Unselect, Idle, Other(CapabilityOther(Atom("LIST-STATUS"))), Other(CapabilityOther(Atom("UIDPLUS")))]+))], completion: Tagged(Tagged { tag: Tag("A001"), body: StatusBody { kind: Ok, code: None, text: Text("Server capabilities") } }) }) sock=[::ffff:xxxx]:48052 aerogramme-1 | 2024-03-02T05:56:53.204434Z INFO aerogramme::imap: runner is quitting aerogramme-1 | 2024-03-02T06:39:50.884159Z INFO aerogramme::imap: IMAP: accepted connection from [::ffff:xxxx]:59856 aerogramme-1 | 2024-03-02T06:39:50.885193Z DEBUG aerogramme::imap: netloop successfully initialized addr=[::ffff:xxxx]:59856 aerogramme-1 | 2024-03-02T06:39:51.142040Z ERROR aerogramme::imap: closing errored netloop core for [::ffff:xxxx]:59856: Received malformed message aerogramme-1 | 2024-03-02T06:39:51.142515Z INFO aerogramme::imap: runner is quitting aerogramme-1 | 2024-03-02T10:40:11.180338Z INFO aerogramme::auth: AUTH: accepted connection from [::1]:59594 aerogramme-1 | 2024-03-02T10:46:54.401758Z INFO aerogramme::auth: Reading buffer empty, connection has been closed. Exiting AUTH session. aerogramme-1 | 2024-03-02T10:46:54.402239Z INFO aerogramme::auth: Auth session succeeded ``` PAR log: ``` aerogramme-1 | 2024-03-02T08:34:43.753986Z INFO aerogramme::imap: IMAP: accepted connection from [::ffff:xxxx]:64896 aerogramme-1 | 2024-03-02T08:34:43.755664Z DEBUG aerogramme::imap: netloop successfully initialized addr=[::ffff:xxxx]:64896 aerogramme-1 | 2024-03-02T08:34:43.861353Z DEBUG aerogramme::imap: command cmd=ImapCommand(Command { tag: Tag("a001"), body: Capability }) sock=[::ffff:xxxx]:64896 aerogramme-1 | 2024-03-02T08:34:43.861512Z DEBUG aerogramme::imap::flow: try change state state=NotAuthenticated transition=None aerogramme-1 | 2024-03-02T08:34:43.861547Z DEBUG aerogramme::imap::flow: transition succeeded state=NotAuthenticated aerogramme-1 | 2024-03-02T08:34:43.861579Z DEBUG aerogramme::imap: response cmd=Response(Response { body: [Data(Capability([Imap4Rev1, Move, Enable, Idle, Other(CapabilityOther(Atom("UIDPLUS"))), Other(CapabilityOther(Atom("LIST-STATUS"))), Unselect, LiteralPlus, Other(CapabilityOther(Atom("CONDSTORE")))]+))], completion: Tagged(Tagged { tag: Tag("a001"), body: StatusBody { kind: Ok, code: None, text: Text("Server capabilities") } }) }) sock=[::ffff:xxxx]:64896 aerogramme-1 | 2024-03-02T08:34:44.116749Z ERROR aerogramme::imap: closing errored netloop core for [::ffff:xxxx]:64896: Received malformed message aerogramme-1 | 2024-03-02T08:34:44.117115Z INFO aerogramme::imap: runner is quitting aerogramme-1 | 2024-03-02T09:11:48.381699Z INFO aerogramme::auth: AUTH: accepted connection from [::1]:59434 aerogramme-1 | 2024-03-02T09:11:48.382206Z DEBUG aerogramme::auth: Made progress state=HandshakePart(Version { major: 1, minor: 0 }) aerogramme-1 | 2024-03-02T09:11:48.382347Z DEBUG aerogramme::auth: Made progress state=HandshakeDone aerogramme-1 | 2024-03-02T09:18:30.821344Z INFO aerogramme::auth: Reading buffer empty, connection has been closed. Exiting AUTH session. aerogramme-1 | 2024-03-02T09:18:30.821634Z INFO aerogramme::auth: Auth session succeeded aerogramme-1 | 2024-03-02T09:34:01.935501Z INFO aerogramme::auth: AUTH: accepted connection from [::1]:36072 aerogramme-1 | 2024-03-02T09:34:01.936079Z DEBUG aerogramme::auth: Made progress state=HandshakePart(Version { major: 1, minor: 0 }) aerogramme-1 | 2024-03-02T09:34:01.936165Z DEBUG aerogramme::auth: Made progress state=HandshakeDone aerogramme-1 | 2024-03-02T09:35:42.548789Z INFO aerogramme::auth: Reading buffer empty, connection has been closed. Exiting AUTH session. aerogramme-1 | 2024-03-02T09:35:42.549144Z INFO aerogramme::auth: Auth session succeeded aerogramme-1 | 2024-03-02T11:19:49.714736Z INFO aerogramme::imap: IMAP: accepted connection from [::ffff:xxxx]:60274 aerogramme-1 | 2024-03-02T11:19:49.715693Z DEBUG aerogramme::imap: netloop successfully initialized addr=[::ffff:xxxx]:60274 aerogramme-1 | 2024-03-02T11:19:49.716149Z ERROR aerogramme::imap: closing errored netloop core for [::ffff:xxxx]:60274: Received malformed message aerogramme-1 | 2024-03-02T11:19:49.716658Z DEBUG aerogramme::imap: command cmd=ImapCommand(Command { tag: Tag("A001"), body: Capability }) sock=[::ffff:XXXX]:60274 aerogramme-1 | 2024-03-02T11:19:49.716849Z DEBUG aerogramme::imap::flow: try change state state=NotAuthenticated transition=None aerogramme-1 | 2024-03-02T11:19:49.716888Z DEBUG aerogramme::imap::flow: transition succeeded state=NotAuthenticated aerogramme-1 | 2024-03-02T11:19:49.716929Z DEBUG aerogramme::imap: response cmd=Response(Response { body: [Data(Capability([Imap4Rev1, Move, Enable, Idle, Other(CapabilityOther(Atom("UIDPLUS"))), Other(CapabilityOther(Atom("LIST-STATUS"))), Unselect, LiteralPlus, Other(CapabilityOther(Atom("CONDSTORE")))]+))], completion: Tagged(Tagged { tag: Tag("A001"), body: StatusBody { kind: Ok, code: None, text: Text("Server capabilities") } }) }) sock=[::ffff:xxxx]:60274 aerogramme-1 | 2024-03-02T11:19:49.717099Z INFO aerogramme::imap: runner is quitting ``` I don't remember why but I suppose a lock issue between the Dovecot Auth protocol and the IMAP runner. Something like acquiring a RW lock and blocking the whole server.

quentin commented

2024-03-02 11:52:26 +00:00

Author

Owner

WAW:

last successful IMAP command: 2024-03-02T05:56:53.204282Z
restart: 2024-03-02T11:39:54.268600Z

PAR:

last successful IMAP command: 2024-03-02T11:19:49.716929Z
restart: 2024-03-02T11:37:28.704570Z

Nothing strange on the postfix side.

WAW: - last successful IMAP command: `2024-03-02T05:56:53.204282Z` - restart: `2024-03-02T11:39:54.268600Z ` PAR: - last successful IMAP command: `2024-03-02T11:19:49.716929Z` - restart: `2024-03-02T11:37:28.704570Z` Nothing strange on the postfix side.