Perhaps my logging is more verbose than default, but every time the word "sasl" appears in a line it appears with an email address and a Queue-ID.
Example:
Aug 13 10:27:08 [REDACTED] postfix/smtpd[16441]: 002B082568: client=c-[MY DOMAIN][IP ADDRESS], sasl_method=PLAIN, sasl_username=[MY USERNAME]
Aug 13 11:50:19 [REDACTED] postfix/smtpd[27412]: 405DE80273: client=c-[MY DOMAIN][IP ADDRESS], sasl_method=PLAIN, sasl_username=[MY USERNAME]
Aug 13 12:35:53 [REDACTED] postfix/smtpd[5727]: 693CF824FC: client=c-[MY DOMAIN][IP ADDRESS], sasl_method=PLAIN, sasl_username=[MY USERNAME]
Aug 13 13:33:31 [REDACTED] postfix/smtpd[4727]: 5970F82581: client=c-[MY DOMAIN][IP ADDRESS], sasl_method=PLAIN, sasl_username=[MY USERNAME]
Aug 14 09:30:15 [REDACTED] postfix/smtpd[24214]: 806EC81A44: client=c-[MY DOMAIN][IP ADDRESS], sasl_method=PLAIN, sasl_username=[MY USERNAME]
Aug 15 09:32:27 [REDACTED] postfix/smtpd[18100]: 5FE908256B: client=c-[MY DOMAIN][IP ADDRESS], sasl_method=PLAIN, sasl_username=[MY USERNAME]
Aug 15 13:11:46 [REDACTED] postfix/smtpd[12178]: D6948825B4: client=c-[MY DOMAIN][IP ADDRESS], sasl_method=PLAIN, sasl_username=[MY USERNAME]
Aug 15 13:25:39 [REDACTED] postfix/smtpd[21525]: F15F782592: client=c-[MY DOMAIN][IP ADDRESS], sasl_method=PLAIN, sasl_username=[MY USERNAME]
In fact, the following command returns no results at all.
"sudo egrep sasl maillog-20140817 | grep -v @"
That being said, and correct me if I am wrong, I believe there should have been a log entry containing “overwhelms.desiro.asia” and “sasl” and it should also contain the Queue-ID (26379802F0) just like it does for all other valid users of the system.
Here is what a normal sample of my log looks like for a message being routed through the system tracking both Queue-ID and queued_as. It is clear that the first entry contains both Queue-ID and sasl username.
“sudo egrep 'AE7A882592|232ED82593' /var/log/maillog”
sudo egrep 'AE7A882592|232ED82593' /var/log/maillog
Aug 18 08:31:12 [REDACTED] postfix/smtpd[18693]: AE7A882592: client=[REDACTED].[OUR DOMAIN][127.0.0.1], sasl_method=LOGIN, sasl_username=[CUSTOMER EMAIL]
Aug 18 08:31:12 [REDACTED] postfix/cleanup[18713]: AE7A882592: message-id=<ebe709f4cd698b92777997a0d05d9437@[CUSTOMER DOMAIN]>
Aug 18 08:31:12 [REDACTED] postfix/qmgr[11844]: AE7A882592: from=<[CUSTOMER EMAIL]>, size=1939, nrcpt=1 (queue active)
Aug 18 08:31:12 [REDACTED] roundcube: User [CUSTOMER EMAIL] [[CUSTOMER IP]]; Message for [RECIPIENT]; 250: 2.0.0 Ok: queued as AE7A882592
Aug 18 08:31:18 [REDACTED] postfix/smtpd[17890]: 232ED82593: client=[REDACTED].[OUR DOMAIN][127.0.0.1]
Aug 18 08:31:18 [REDACTED] postfix/cleanup[18713]: 232ED82593: message-id=<ebe709f4cd698b92777997a0d05d9437@[CUSTOMER DOMAIN]>
Aug 18 08:31:18 [REDACTED] postfix/qmgr[11844]: 232ED82593: from=<[CUSTOMER EMAIL]>, size=2401, nrcpt=1 (queue active)
Aug 18 08:31:18 [REDACTED] amavis[20010]: (20010-08) Passed CLEAN {RelayedOutbound}, MYNETS LOCAL [127.0.0.1]:46242 [127.0.0.1] <[CUSTOMER EMAIL]> -> <[RECIPIENT]>, Queue-ID: AE7A882592, Message-ID: <ebe709f4cd698b92777997a0d05d9437@[CUSTOMER DOMAIN]>, mail_id: JIQBGtbIfO8R, Hits: -11.899, size: 1939, queued_as: 232ED82593, 5411 ms
Aug 18 08:31:18 [REDACTED] postfix/smtp[19487]: AE7A882592: to=<[RECIPIENT]>, relay=127.0.0.1[127.0.0.1]:10024, delay=5.5, delays=0.09/0/0.01/5.4, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 232ED82593)
Aug 18 08:31:18 [REDACTED] postfix/qmgr[11844]: AE7A882592: removed
Aug 18 08:33:46 [REDACTED] postfix/smtp[20377]: 232ED82593: to=<[RECIPIENT]>, relay=newclients-com.mail.protection.outlook.com[[RECIPIENT IP]]:25, delay=148, delays=0.04/0.01/4.3/144, dsn=2.6.0, status=sent (250 2.6.0 <ebe709f4cd698b92777997a0d05d9437@[CUSTOMER DOMAIN]> [InternalId=38220913971934, Hostname=BN1PR05MB342.namprd05.prod.outlook.com] Queued mail for delivery)
Aug 18 08:33:46 [REDACTED] postfix/qmgr[11844]: 232ED82593: removed
Now, in contrast, here’s what the message that ramonp@overwhelms.desiro.asia sent through our system looks like:
“sudo egrep '26379802F0|37AA882410' /var/log/maillog-20140817”
Aug 15 08:37:42 [REDACTED] postfix/smtpd[8434]: 26379802F0: client=unknown[93.158.215.139]
Aug 15 08:37:42 [REDACTED] postfix/cleanup[8215]: 26379802F0: message-id=<F908E09D.2C58.E93B.8F4E@desiro.asia>
Aug 15 08:37:43 [REDACTED] postfix/qmgr[2388]: 26379802F0: from=<ramonp@overwhelms.desiro.asia>, size=415146, nrcpt=3 (queue active)
Aug 15 08:37:48 [REDACTED] postfix/smtpd[9971]: 37AA882410: client=[REDACTED].[OUR DOMAIN][127.0.0.1]
Aug 15 08:37:48 [REDACTED] postfix/cleanup[8215]: 37AA882410: message-id=<F908E09D.2C58.E93B.8F4E@desiro.asia>
Aug 15 08:37:48 [REDACTED] postfix/qmgr[2388]: 37AA882410: from=<ramonp@overwhelms.desiro.asia>, size=415598, nrcpt=1 (queue active)
Aug 15 08:37:48 [REDACTED] amavis[9412]: (09412-07) Passed CLEAN {RelayedOutbound}, LOCAL [93.158.215.139]:48633 [93.158.215.139] <ramonp@overwhelms.desiro.asia> -> <c7-w7@hotmail.com>, Queue-ID: 26379802F0, Message-ID: <F908E09D.2C58.E93B.8F4E@desiro.asia>, mail_id: skmMeFMU6b0y, Hits: 1.396, size: 415146, queued_as: 37AA882410, 4500 ms
Aug 15 08:37:48 [REDACTED] postfix/smtp[9206]: 26379802F0: to=<c7-w7@hotmail.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=8.7, delays=4.1/0/0.01/4.6, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 37AA882410)
Aug 15 08:37:48 [REDACTED] postfix/qmgr[2388]: 26379802F0: removed
Aug 15 08:37:49 [REDACTED] postfix/smtp[10098]: 37AA882410: to=<c7-w7@hotmail.com>, relay=mx3.hotmail.com[65.55.33.135]:25, delay=1.4, delays=0.11/0/0.25/1, dsn=2.0.0, status=sent (250 <F908E09D.2C58.E93B.8F4E@desiro.asia> Queued mail for delivery)
Aug 15 08:37:49 [REDACTED] postfix/qmgr[2388]: 37AA882410: removed
The line that is supposed to contain the sasl username (the line with “postfix/smtpd” in it, the first one) only contains this:
“Aug 15 08:37:42 [REDACTED] postfix/smtpd[8434]: 26379802F0: client=unknown[93.158.215.139]”
Both entries consists of the same information. In my thinking the information provided should contain all of the same fields but it doesn’t. I also went and checked around each entry going through around 1000 lines of logs and turned up nothing. Maybe I'm looking at this wrong but I cannot explain any better what I'm finding.
Why doesn’t the message that ramonp@overwhelms.desiro.asia sent have any sasl username associated with it? Why didn’t they have to login to send it through the system? How is something like this possible?
Sorry to keep pressing you but this is a real problem for us over here. Our server is doing this 1000's of times a day.
Edit: I even have another example where the line that should cantain the sasl username doesn't not but actually contains something other than "unknown". lgamerica.lgamerica.com is not valid user of our system ye they are using our system to send their mail with.
"sudo egrep '506DA82590|01320825C0' /var/log/maillog" ( grepping for queue_id and queued_as)
Aug 18 16:33:05 [REDACTED] postfix/smtpd[16588]: 506DA82590: client=lgamerica.lgamerica.com[63.139.123.170]
Aug 18 16:33:05 [REDACTED] postfix/cleanup[20530]: 506DA82590: message-id=<>
Aug 18 16:33:05 [REDACTED] postfix/qmgr[11844]: 506DA82590: from=<md-uwteam-d@lgamerica.com>, size=4636, nrcpt=1 (queue active)
Aug 18 16:33:08 [REDACTED] postfix/smtpd[19146]: 01320825C0: client=[REDACTED].[OUR DOMAIN][127.0.0.1]
Aug 18 16:33:08 [REDACTED] postfix/cleanup[20977]: 01320825C0: message-id=<20140818203308.01320825C0@smtp.[OWR DOMAIN]>
Aug 18 16:33:08 [REDACTED] postfix/qmgr[11844]: 01320825C0: from=<md-uwteam-d@lgamerica.com>, size=5279, nrcpt=1 (queue active)
Aug 18 16:33:08 [REDACTED] amavis[21130]: (21130-07) Passed BAD-HEADER-7 {RelayedOutbound}, LOCAL [63.139.123.170]:61197 [63.139.123.170] <md-uwteam-d@lgamerica.com> -> <lboughman@dixonwells.com>, Queue-ID: 506DA82590, mail_id: 59GmrNn_cBLw, Hits: -0.691, size: 4635, queued_as: 01320825C0, 2618 ms
Aug 18 16:33:08 [REDACTED] postfix/smtp[21129]: 506DA82590: to=<lboughman@dixonwells.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=5.8, delays=3.2/0/0.01/2.7, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 01320825C0)
Aug 18 16:33:08 [REDACTED] postfix/qmgr[11844]: 506DA82590: removed
Aug 18 16:33:13 [REDACTED] postfix/smtp[21059]: 01320825C0: to=<lboughman@dixonwells.com>, relay=dixonwells-com.mail.eo.outlook.com[207.46.163.215]:25, delay=5.5, delays=0.04/0.01/2.1/3.4, dsn=2.6.0, status=sent (250 2.6.0 <20140818203308.01320825C0@smtp.[OWR DOMAIN]> [InternalId=17274358472984, Hostname=BLUPR04MB837.namprd04.prod.outlook.com] Queued mail for delivery)
Aug 18 16:33:13 [REDACTED] postfix/qmgr[11844]: 01320825C0: removed