Hello,
i would like to construct a complete transaction of a mail session, starting from the customer smtp connection, until the final delivery of the message.
I have some ironport mail logs, with inside some fields. They should compare in logical order in every session,starting from the first:
ICID: smtp connection ID
MID: message internal ID
DCID: delivery connection ID, alias the final delivery (local or remote)
Basically, i have to find the start of the connection (which starts always with "New SMTP ICID", then (and ONLY IF the message composing is going to happen, sometimes clients drop the connection) there's a line with MID and ICID in the same event, then use the MID until i find another line with both MID and DCID.
Finally, correlate them all together.
Here are example sessions to make thing clearer(anonimized,sorry):
example1. Full session, with message delivery:
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: New SMTP ICID 1513562731 interface smtpout (1.2.3.4) address 123.2.2.2 reverse dns host host.domain.it verified yes
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: ICID 1513562731 RELAY SG Servers_bypass_AntiSpam match 195.110.129.0/24 SBRS not enabled
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: SMTP Auth: (ICID 1513562731) succeeded for user: xxx@yyy.it using AUTH mechanism: PLAIN with profile: SmtpAuth_CGP_LDAP
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: Start MID 182684958 ICID 1513562731
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: MID 182684958 ICID 1513562731 From: <xxx@yyy.it>
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: MID 182684958 ICID 1513562731 RID 0 To: <zzz@yyy.it>
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: MID 182684958 Message-ID '<4E4CD693.3090603@yyy.it>'
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: MID 182684958 Subject 'something'
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: MID 182684958 ready 15669 bytes from <xxx@yyy.it>
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: ICID 1513562731 close
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: MID 182684958 rewritten to MID 182684959 by LDAP rewrite
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: LDAP: Reroute query Produzione.routing MID 182684958 RID 0 address zzz@yyy.it to [('zzz@yyy.it', 'mailhost.it')]
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: LDAP: Mailhost query Produzione.routing MID 182684958 address xxx@yyy.it to mailhost.it
Aug 18 11:08:32 splunk_mail_logs_indexer1: Info: Message finished MID 182684958 done
example 2. SMTP session, mail server stops client from sending message:
Aug 18 11:09:20 splunk_mail_logs_indexer1: Info: New SMTP ICID 675888601 interface smtpout (1.2.3.4) address 123.44.2.21 reverse dns host host.domain.it verified yes
Aug 18 11:09:20 splunk_mail_logs_indexer1: Info: ICID 675888601 RELAY SG Servers_bypass_AntiSpam match 195.110.129.0/24 SBRS not enabled
Aug 18 11:09:32 splunk_mail_logs_indexer1: Info: Start MID 396231626 ICID 675888601
Aug 18 11:09:32 splunk_mail_logs_indexer1: Info: MID 396231626 ICID 675888601 From: <user@domain.eu>
Aug 18 11:09:40 splunk_mail_logs_indexer1: Info: MID 396231626 ICID 675888601 RID 0 To: <user2@domain.eu>
Aug 18 11:09:42 splunk_mail_logs_indexer1: Info: Message aborted MID 396231626 Receiving aborted by sender
Aug 18 11:09:42 splunk_mail_logs_indexer1: Info: Message finished MID 396231626 aborted
Aug 18 11:09:42 splunk_mail_logs_indexer1: Info: ICID 675888601 close
I have a huge turnover of sessions on this mail frontend server, in just 1 second i can have thousand of sessions. Since i'm searching for sessions originated from a particular IP, the others are not relevant to me.
Problem is, that i know that session ends with "Message finished" when a message exists, and "ICID close" when not. ICID close, however happens every time, since is when the client disconnects (after leaving the server to take care of the message) and happens BEFORE the "message finished (see example 1)
This leads to incorrect parsing of transaction when I have a lot of events related to IP not relevant to my search.
In fact, if i "purge" logs from these transactions - using nested subsearches - transaction command starts to behave correctly.
To summarize, purging unrelevant events BEFORE transaction works (but I think this is not efficient as it should be):
earliest=-1h@m index=sistemi_legale sourcetype=ironport_mail_logs [search earliest=-1h@m index="sistemi_legale" host=ironportout* sourcetype=ironport_mail_logs Start MID [ search earliest=-1h@m index="sistemi_legale" host=ironportout* sourcetype=ironport_mail_logs New SMTP ICID RemoteIP=1.2.3.4|fields host ICID | format maxresults=50000 ] | fields host ICID MID | eval query="host=".host." (ICID=".ICID.") OR (MID=".MID.") OR (DCID MID=".MID.")"|fields query]|transaction ICID MID DCID host startswith="New SMTP ICID"
This instead, leads to wrong transactions (but is easier to read, and IMHO SHOULD work):
earliest=-1h@m index="sistemi_legale" host=ironportout* sourcetype=ironport_mail_logs RemoteIP=1.2.3.4 (MID=* OR ICID=* OR DCID=*)|transaction MID ICID DCID host maxspan=300s startswith="New SMTP ICID"
I've found that the transaction command is not as effective with multiple fields as when using one field only; on the other hand, during my test, using "startswith" and "endswith" helps dramatically in identified complete and correct transactions.
Could anyone help?
Thanks in advance.
... View more