Possible SSL Related Issue
Need some help in resolving the issue described below and would greatly appreciate any assistance. Please let me know if any additional information is required. Thank you.
Updated Postfix with signed certificates from self signed and am experiencing several new log entries that I am unable to identify. See history that follows.
Self signed certificate in Postfix with pop3. Has worked this way since original install. Dec 29 00:12:41 mail dovecot: pop3-login: Login: user=<usr1>, method=PLAIN, rip=209.197.77.67, lip=10.0.1.211, mpid=15448, TLS, session=<CuXLvmEqzM/RxU1D> Dec 29 00:12:41 mail dovecot: pop3(usr1): Disconnected: Logged out top=0/0, retr=0/0, del=0/2825, size=204691614
Updated log entry for signed certificate in Postfix. Original self signed certificate still used in Dovecot. Note new disconnect record with information such as <136791><t3CWAKwqpieu9RkM> before the Disconnected message. Unable to find anything about these codes. Jan 1 16:48:12 mail dovecot: pop3-login: Login: user=<usr1>, method=PLAIN, rip=174.245.25.12, lip=10.0.1.211, mpid=136791, TLS, session=<t3CWAKwqpieu9RkM> Jan 1 16:48:13 mail dovecot: pop3(usr1)<136791><t3CWAKwqpieu9RkM>: Disconnected: Logged out top=0/0, retr=0/0, del=0/2867, size=206803370
Self signed certificate in Postfix with imap. Dec 29 00:06:30 mail dovecot: imap-login: Login: user=<usr2>, method=PLAIN, rip=10.0.1.101, lip=10.0.1.211, mpid=15104, TLS, session=<bZezqGEqBMMKAAFl> Dec 29 00:06:31 mail dovecot: imap(usr2): Connection closed (SELECT finished 0.177 secs ago) in=102 out=952
Updated non self signed certificate in Postfix. Original self signed certificate still used in Dovecot. Similar information before Disconnect message. Jan 1 16:55:00 mail dovecot: imap-login: Login: user=<usr2>, method=PLAIN, rip=10.0.1.4, lip=10.0.1.211, mpid=136855, TLS, session=<Z/7hGKwqntEKAAEE> Jan 1 16:55:00 mail dovecot: imap(usr2)<136855><Z/7hGKwqntEKAAEE>: Connection closed (SELECT finished 0.117 secs ago) in=106 out=1012 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
Issue persists and appears worse when attempting to access the mail server with the Rainloop web application. Rainloop log messages before signed certificate update appeared as the following: Dec 29 07:09:17 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=20215, TLS, session=<xTGtkGcqKNgKAAHT> Dec 29 07:09:17 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=20216, TLS, session=<azKtkGcqMtgKAAHT> Dec 29 07:09:17 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=20217, TLS, session=<Qz2tkGcqOtgKAAHT> Dec 29 07:09:17 mail dovecot: imap(usr): Logged out in=211 out=2047 Dec 29 07:09:17 mail dovecot: imap(usr): Logged out in=28 out=787 Dec 29 07:09:17 mail dovecot: imap(usr): Logged out in=80 out=1449 Dec 29 07:09:17 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=20218, TLS, session=<0EetkGcqRNgKAAHT> Dec 29 07:09:17 mail dovecot: imap(usr): Logged out in=350 out=1381 Dec 29 07:09:17 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=20220, TLS, session=<U8+vkGcqVNgKAAHT> Dec 29 07:09:17 mail dovecot: imap(usr): Logged out in=713 out=66680 Dec 29 07:09:24 mail dovecot: imap(usr): Connection closed (SELECT finished 0.176 secs ago) in=110 out=970
But now contain the same type of <141032><n0r2ZbAqLLMKAAHT> entries before Logged out and seems to be completing significantly more logins and logouts. Note the web interface is working. Jan 1 22:02:53 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141032, TLS, session=<n0r2ZbAqLLMKAAHT> Jan 1 22:02:53 mail dovecot: imap(usr)<141032><n0r2ZbAqLLMKAAHT>: Logged out in=11 out=457 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Jan 1 22:02:53 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141034, TLS, session=<4OP7ZbAqOLMKAAHT> Jan 1 22:02:53 mail dovecot: imap(usr)<141034><4OP7ZbAqOLMKAAHT>: Logged out in=80 out=1470 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Jan 1 22:02:54 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141038, TLS, session=<Grz9ZbAqSLMKAAHT> Jan 1 22:02:54 mail dovecot: imap(usr)<141038><Grz9ZbAqSLMKAAHT>: Logged out in=342 out=1473 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Jan 1 22:02:54 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141039, TLS, session=<+Mf9ZbAqVLMKAAHT> Jan 1 22:02:54 mail dovecot: imap(usr)<141039><+Mf9ZbAqVLMKAAHT>: Logged out in=693 out=37481 deleted=0 expunged=0 trashed=0 hdr_count=20 hdr_bytes=20978 body_count=0 body_bytes=0 Jan 1 22:02:59 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141041, TLS, session=<MxRKZrAq6IcKAAHT> Jan 1 22:02:59 mail dovecot: imap(usr)<141041><MxRKZrAq6IcKAAHT>: Logged out in=28 out=881 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Jan 1 22:03:07 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141043, TLS, session=<SsLKZrAq7ocKAAHT> Jan 1 22:03:07 mail dovecot: imap(usr)<141043><SsLKZrAq7ocKAAHT>: Logged out in=525 out=10554 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=3522 body_count=1 body_bytes=4807 Jan 1 22:03:08 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141045, TLS, session=<b2/bZrAq/IcKAAHT> Jan 1 22:03:08 mail dovecot: imap(usr)<141045><b2/bZrAq/IcKAAHT>: Logged out in=523 out=15895 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=947 body_count=1 body_bytes=13215 Jan 1 22:03:09 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141047, TLS, session=<P3XrZrAqsJYKAAHT> Jan 1 22:03:09 mail dovecot: imap(usr)<141047><P3XrZrAqsJYKAAHT>: Logged out in=523 out=8719 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=779 body_count=1 body_bytes=6300 Jan 1 22:03:10 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141049, TLS, session=<JmD7ZrAqwJYKAAHT> Jan 1 22:03:10 mail dovecot: imap(usr)<141049><JmD7ZrAqwJYKAAHT>: Logged out in=523 out=13125 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=780 body_count=1 body_bytes=10700 Jan 1 22:03:11 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141051, TLS, session=<kkoLZ7Aq0JYKAAHT> Jan 1 22:03:11 mail dovecot: imap(usr)<141051><kkoLZ7Aq0JYKAAHT>: Logged out in=523 out=8022 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=800 body_count=1 body_bytes=5582 Jan 1 22:03:12 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141055, TLS, session=<7ywbZ7Aq4JYKAAHT> Jan 1 22:03:12 mail dovecot: imap(usr)<141055><7ywbZ7Aq4JYKAAHT>: Logged out in=523 out=13955 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=1113 body_count=1 body_bytes=11104 Jan 1 22:03:13 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141057, TLS, session=<JAMrZ7Aq6JYKAAHT> Jan 1 22:03:13 mail dovecot: imap(usr)<141057><JAMrZ7Aq6JYKAAHT>: Logged out in=523 out=14232 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=774 body_count=1 body_bytes=11814 Jan 1 22:03:14 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141059, TLS, session=<lvE6Z7Aq9JYKAAHT> Jan 1 22:03:14 mail dovecot: imap(usr)<141059><lvE6Z7Aq9JYKAAHT>: Logged out in=523 out=6987 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=749 body_count=1 body_bytes=4599 Jan 1 22:03:15 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141061, TLS, session=<6NdKZ7AqBJcKAAHT> Jan 1 22:03:15 mail dovecot: imap(usr)<141061><6NdKZ7AqBJcKAAHT>: Logged out in=523 out=7126 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=812 body_count=1 body_bytes=4676 Jan 1 22:03:16 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141063, TLS, session=<ebpaZ7AqCJcKAAHT> Jan 1 22:03:16 mail dovecot: imap(usr)<141063><ebpaZ7AqCJcKAAHT>: Logged out in=523 out=26116 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=861 body_count=1 body_bytes=23498 Jan 1 22:03:17 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141065, TLS, session=<2aRqZ7AqDJcKAAHT> Jan 1 22:03:17 mail dovecot: imap(usr)<141065><2aRqZ7AqDJcKAAHT>: Logged out in=523 out=8776 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=775 body_count=1 body_bytes=6374 Jan 1 22:03:18 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141067, TLS, session=<b4d6Z7AqAOIKAAHT> Jan 1 22:03:18 mail dovecot: imap(usr)<141067><b4d6Z7AqAOIKAAHT>: Logged out in=523 out=9875 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=749 body_count=1 body_bytes=7498 Jan 1 22:03:20 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141069, TLS, session=<a3GKZ7AqCuIKAAHT> Jan 1 22:03:20 mail dovecot: imap(usr)<141069><a3GKZ7AqCuIKAAHT>: Logged out in=523 out=61311 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=1153 body_count=1 body_bytes=58591 Jan 1 22:03:21 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141071, TLS, session=<AHuaZ7AqDuIKAAHT> Jan 1 22:03:21 mail dovecot: imap(usr)<141071><AHuaZ7AqDuIKAAHT>: Logged out in=523 out=9458 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=1150 body_count=1 body_bytes=6745 Jan 1 22:03:22 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141073, TLS, session=<X2WqZ7AqGuIKAAHT> Jan 1 22:03:22 mail dovecot: imap(usr)<141073><X2WqZ7AqGuIKAAHT>: Logged out in=523 out=11885 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=772 body_count=1 body_bytes=9482 Jan 1 22:03:23 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141075, TLS, session=<eEu6Z7AqKOIKAAHT> Jan 1 22:03:23 mail dovecot: imap(usr)<141075><eEu6Z7AqKOIKAAHT>: Logged out in=523 out=8665 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=777 body_count=1 body_bytes=6326 Jan 1 22:03:24 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141077, TLS, session=</i3KZ7AqOOIKAAHT> Jan 1 22:03:24 mail dovecot: imap(usr)<141077></i3KZ7AqOOIKAAHT>: Logged out in=523 out=42692 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=778 body_count=1 body_bytes=40360 Jan 1 22:03:25 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141079, TLS, session=<NCDaZ7AqOuIKAAHT> Jan 1 22:03:25 mail dovecot: imap(usr)<141079><NCDaZ7AqOuIKAAHT>: Logged out in=523 out=19469 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=1641 body_count=1 body_bytes=16070 Jan 1 22:03:26 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141081, TLS, session=<QAfqZ7AqPuIKAAHT> Jan 1 22:03:26 mail dovecot: imap(usr)<141081><QAfqZ7AqPuIKAAHT>: Logged out in=523 out=9596 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=858 body_count=1 body_bytes=7098 Jan 1 22:03:29 mail dovecot: imap-login: Login: user=<usr>, method=PLAIN, rip=10.0.1.211, lip=10.0.1.211, mpid=141083, TLS, session=<AgEYaLAqgLUKAAHT> Jan 1 22:03:29 mail dovecot: imap(usr)<141083><AgEYaLAqgLUKAAHT>: Logged out in=523 out=11342 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=1188 body_count=1 body_bytes=8581 Jan 1 22:10:40 mail dovecot: imap(usr)<141310><rUXLgbAqGq8KAAE8>: Connection closed (SELECT finished 0.074 secs ago) in=101 out=966 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
On 02.01.25 15:57, via dovecot wrote:
Updated Postfix with signed certificates from self signed and am experiencing several new log entries that I am unable to identify. See history that follows. [...]
- Updated log entry for signed certificate in Postfix. Original self signed certificate still used in Dovecot. Note new disconnect record with information such as <136791><t3CWAKwqpieu9RkM> before the Disconnected message. Unable to find anything about these codes. Jan 1 16:48:12 mail dovecot: pop3-login: Login: user=<usr1>, method=PLAIN, rip=174.245.25.12, lip=10.0.1.211, mpid=136791, TLS, session=<t3CWAKwqpieu9RkM> Jan 1 16:48:13 mail dovecot: pop3(usr1)<136791><t3CWAKwqpieu9RkM>: Disconnected: Logged out top=0/0, retr=0/0, del=0/2867, size=206803370
IMHO that has nothing to do with Postfix and/oder your certs.
Which distribution and especially which version of Dovecot are you running? Were there changes too? On my Debian 12 with Dovecot 2.3.19 I have the same log entries like you. And they are resulting from:
# doveconf -d | grep mail_log_prefix mail_log_prefix = "%s(%u)<%{pid}><%{session}>: "
And in /etc/dovecot/conf.d/10-logging.conf
you can find this:
--- snip --- ## ## Log formatting. ##
[...]
# Log prefix for mail processes. See doc/wiki/Variables.txt for list of # possible variables you can use. #mail_log_prefix = "%s(%u)<%{pid}><%{session}>: " --- snip ---
More details regarding the variables you can find here:
https://doc.dovecot.org/2.3/configuration_manual/config_file/config_variable...
And if you look at: https://doc.dovecot.org/2.3/installation_guide/upgrading/from-2.2-to-2.3/
in the section "Changed Setting Defaults" you find this:
Setting Old Default Value New Default Value ------------------+---------------------+-------------------------- mail_log_prefix "%s(%u): " "%s(%u)<%{pid}><%{session}>: "
And that's exactly the change you observed in your log, I think.
BTW and regarding the rest of these lines: as you can also see in this table, the default value of 'imap_logout_format' has been changed too. And that also corresponds to your new log entries.
You could change 'imap_logout_format' and 'pop3_logout_format' (there was no change of the default) in /etc/dovecot/conf.d/20-imap.conf resp. /etc/dovecot/conf.d/20-pop3.conf.
So from my point of view all is looking fine. ;-)
Regards, Markus
participants (2)
-
bcs＠nanomail.net
-
Markus Winkler