Custom decoder for Microsoft Exchange

[Gennaro Losappio]

Hi,

I am having problems creating a custom decoder to parse Exchange Smtp Receive Logs.
Logs have the following format:
2024-05-09T00:00:19.312Z,server-name\SMTP 587,08DBBB7EF9630D75,1,localip:587,remoteip:55336,*,SMTPSubmit SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender AcceptRoutingHeaders,Set Session Permissions
2024-05-09T00:00:19.312Z,server-name\SMTP 587,08DBBB7EF9630D75,2,localip:587,remoteip:55336,>,"220 MailServerAddress Microsoft ESMTP MAIL Service ready at Thu, 9 May 2024 02:00:19 +0200",
2024-05-09T00:00:19.344Z,server-name\SMTP 25,08DBBB7EF9630D76,0,localip:remoteip:55208,+,,

- Within /var/ossec/etc/decoders I edited local_decoder.xml this way:
<decoder name="SmtpLogs">
<prematch>^server-name\\SMTP \d{2,3},</prematch>
</decoder>

<decoder name="SmtpReceive587">
<parent>SmtpLogs</parent>
<regex offset="after_parent">^\d\d\d\d-\d\d-\d\dT\d\d:\d\d:\d\d\.\d\d\dZ,server-name\\SMTP 587,([A-z0-9]+),(\d+),(\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}:587),(\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}:\d+),(\W),(\.*),(\.*)</rege>
<order>session-id,sequence-number,local-endpoint,remote-endpoint,event,data,context</order>
</decoder>

<decoder name="SmtpReceive25">
<parent>SmtpLogs</parent>
<regex offset="after_parent">^\d\d\d\d-\d\d-\d\dT\d\d:\d\d:\d\d\.\d\d\dZ,server-name\\SMTP 25,([A-Z0-9]+),(\d+),(\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}:25),(\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}:\d+),(\W),(\.*),(\.*)</re>
<order>session-id,sequence-number,local-endpoint,remote-endpoint,event,data,context</order>
</decoder>

- Restarted Wazuh Server but when I look at /var/ossec/logs/archives/archives.json predecoder catches timestamp and a portion of server name, while decoder is empty.


{"timestamp":"2024-05-09T00:16:20.539+0200","agent":{"id":"028","name":"server-name","ip":"localip"},"manager":{"name":"wazuh"},"id":"1715552180.15312486","full_log":"2024-05-12T22:16:11.069Z,server-name\\SMTP 587,08DBBB7EF9649AD4,8,localip:587,remoteip:58030,>,250-ENHANCEDSTATUSCODES,","predecoder":{"timestamp":"2024-05-12T22:16:11.069Z,servern"},"decoder":{},"location":"C:\\Program Files\\path\SmtpReceive\\RECV20240512-1.LOG"}

Running logtest I get the same result:

**Messages:
WARNING: (7003): '7e2d32a7' token expires
WARNING: (7613): Rule ID '100012' does not exist but 'overwrite' is set to 'yes'. Still, the rule will be loaded.
INFO: (7202): Session initialized with token '88bab861'

**Phase 1: Completed pre-decoding.
full event: '2024-05-09T00:00:16.614Z,server-name\SMTP 587,08DBBB7EF9630D74,13,localip:587,remoteip:37346,>,250 CHUNKING,'
timestamp: '2024-05-09T00:00:16.614Z,server-n'

**Phase 2: Completed decoding.
No decoder matched.

[Lucio Donda]

Hi Gennaro Losappio!

It seems that you're having an issue with the Regex, were you able to check it in regex101.com or any other similar tool? 
here's an example of how I changed it (not sure if I'm being as specific as I need to be)

Another thing is, that the third case it isn't matching, is that ok (localip:remoteip:55208) ?
if that matches and the IPs where modified by you, then try adding the pcre2 in the regex. more info here -> https://documentation.wazuh.com/current/user-manual/ruleset/ruleset-xml-syntax/pcre2.html#configuring-pcre
<regex type="pcre2"> .... </regex>
Another detail is, maybe you've copy paste it but there are some issues on the xml's

let me know!

[Gennaro Losappio]

Hi Lucio,
thank you for you replay.

Actually before posting here I tried several combinations of regex, checking them in regex101.com first, but none would change the final result.
I also tried to replace local_decoder.xml with an empty one and when I test the log on wazuh web interface I get the same result:

**Messages:

WARNING: (7613): Rule ID '100012' does not exist but 'overwrite' is set to 'yes'. Still, the rule will be loaded.

INFO: (7202): Session initialized with token '789b9eec'

**Phase 1: Completed pre-decoding.
full event: '2024-05-09T00:00:19.312Z,server-name\SMTP 587,08DBBB7EF9630D75,1,localip:587,remoteip:55336,*,SMTPSubmit SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender AcceptRoutingHeaders,Set Session Permissions'
timestamp: '2024-05-09T00:00:19.312Z,server-n'

**Phase 2: Completed decoding.
No decoder matched.

I then checked if predefined decoders would have a similar data format YYYY-MM-DDTHH:MM:SS.[UTC]Z  causing that wired behaviour on Phase 1:"timestamp: '2024-05-09T00:00:19.312Z,server-n'",.

The only decoderI found having the same date format is  0520-msexchange-log-decoders.xml with:

<!--2021-04-06T14:54:38.677Z,WIN-03FGEGKLSPR,ECP.Request,"S:TIME=4365;S:SID=3a5d3a0b-a544-4d5c-9b1d-3d33d4968b48;'S:CMD=Set-OabVirtualDirectory.ExternalUrl=''http://o/#<sanitized>bad code goes here</sanitized>>
<decoder name="ECPServerLog">
  <prematch type="pcre2">,ECP\.Request,</prematch>
</decoder>

<!-- 2021-04-06T14:54:34.255Z,61d2c86f-f9bb-456d-88c0-3529172510ac,15,0,847,30,,Ecp,192.168.0.60,/ecp/lkO.js,,FBA,False,,,ServerInfo~Admin@WIN-03FGEGKLSPR:444/ecp/DDI/DDIService.svc/GetList?reqId=1615583487987>
<decoder name="HTTPProxyLog">
  <prematch type="pcre2">-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{12},.*,Ecp,</prematch>
</decoder>

so within my server /var/ossec/etc/ossec.conf within <ruleset>tags I added:

<decoder_exclude>0520-msexchange-log-decoders.xml</decoder_exclude>

<rule_exclude>  0910-ms-exchange-proxylogon_rules.xml </rule_exclude>

but when I go and test the log I get again the same result:

**Messages: WARNING: (7613): Rule ID '100012' does not exist but 'overwrite' is set to 'yes'. Still, the rule will be loaded. INFO: (7202): Session initialized with token 'c97798fe' **Phase 1: Completed pre-decoding. full event: '2024-05-09T00:00:19.312Z,server-name\SMTP 587,08DBBB7EF9630D75,1,localip:587,remoteip:55336,*,SMTPSubmit SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender AcceptRoutingHeaders,Set Session Permissions' timestamp: '2024-05-09T00:00:19.312Z,server-n' **Phase 2: Completed decoding. No decoder matched.

[Gennaro Losappio]

Lucio, I tryed using the following regex too: "\d\d\d\d-\d\d-\d\dT\d\d:\d\d:\d\d\.\d\d\dZ,ZMAIL2010\\SMTP 587,([A-z0-9]+),(\d+),(\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}:587),(\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}:\d+),(\W*),(.*),(.*)" but nothing changed. I believe there must be a rule intercepting my log date format and preventing my custom decoder to parse the entire log.

May it be possible? How may I further investigate?

[Gennaro Losappio]

Some updates: I applied solution found here (https://github.com/wazuh/wazuh/issues/3525), so in our Exchange server agent ossec.conf I'have added between the <localfile>tags, the string "<out_format>$(timestamp) server-name sample:$(log)</out_format>".

If I test the log within the Dashboard test tool, I still get that " timestamp: '2024-05-09T00:00:19.312Z,server-n'" in Phase 1, but if I read archives.log I see:

2024 May 14 14:48:04 (server-name) any->C:\Program Files\Microsoft\Exchange Server\path\RECV20240514-1.LOG May 14 14:48:01 server-name sample:2024-05-14T12:47:59.799Z,server-name\SMTP 587,08DBBB7EF9658F94,15,localip:587,remoteip:50581,>,334 <authentication response>,

Any idea?

[Lucio Donda]

Hi Gennaro, sorry for the late response.
out_format can be used as a way of log enrichment before sending the event to the manager. I don't know how you are collecting those logs but it could work in that stage:
do modify the ossec.conf (supose that you fetch that from a file in log path):

<localfile>
<log_format>syslog</log_format>
<location>[log path]</location>
<out_format>$(timestamp) MicrosoftExchange $(log)</out_format>
</localfile>

$() plays the role of a variable, some have an specific name (more details on the documentation -> https://documentation.wazuh.com/current/user-manual/reference/ossec-conf/localfile.html#out-format ).

this will modify the above event:

2024 May 14 14:48:04 (server-name) any->C:\Program Files\Microsoft\Exchange Server\path\RECV20240514-1.LOG May 14 14:48:01 server-name sample:2024-05-14T12:47:59.799Z,server-name\SMTP 587,08DBBB7EF9658F94,15,localip:587,remoteip:50581,>,334 <authentication response>,

Into 

2024 May 14 14:48:04 MicrosoftExchange (server-name) any->C:\Program Files\Microsoft\Exchange Server\path\RECV20240514-1.LOG May 14 14:48:01 server-name sample:2024-05-14T12:47:59.799Z,server-name\SMTP 587,08DBBB7EF9658F94,15,localip:587,remoteip:50581,>,334 <authentication response>,

In the next step, having that timestamp separated and being able to use that name to identify the source, you could do something like:

<decoder name="custom_mysql">
    <program_name>MicrosoftExchange</program_name>
    <regex type="pcre2">YOU-REGEX_HERE</regex>
    <order>any-field-you-need</order>
</decoder>

In your case, you are adding  (server-name) any->C:\Program Files\Microsoft\Exchange Server\path\RECV20240514-1.LOG May 14 14:48:01 to the logs.
that sound as adding server-name (it isn't a match as I said earlier) and (agent-ip)->source. Do try what I've shared earlier and we discuss it.

[Gennaro Losappio]

Thanks Lucio but it doesn't seem to work.

I modified the name of the program_data on the Exchange agent into 'TransportLogs' and modified local_decoder.xml this way:

<decoder name="TransportLogs">
<program_name>TransportLogs</program_name>
<regex type="pcre2">^\d\d\d\d-\d\d-\d\dT\d\d:\d\d:\d\d\.\d\d\dZ,(server-name\\SMTP \d{2,3}),([A-z0-9]+),(\d+),(\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}:587),(\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}:\d+),(\W*),(.*),(.*)</regex>
<order>connector-id,session-id,sequence-number,local-endpoint,remote-endpoint,event,data,context</order>
</decoder>

Now comes the weird fact

On the wazuh webinterface 'Ruleset Test' page I still get on Phase 1:

**Phase 1: Completed pre-decoding. full event: '2024-05-09T00:00:19.312Z,server-name\SMTP 587,08DBBB7EF9630D75,1,localip:587,remoteip:55336,*,SMTPSubmit SMTPAcceptAnySender SMTPAcceptAuthoritativeDomainSender AcceptRoutingHeaders,Set Session Permissions' timestamp: '2024-05-09T00:00:19.312Z,server-n'

why on the last line timestamp contains ",server-n'. I should presume it is not parsing the date format correctly.
BUT
if I go and check the Exchange server Security Events, wazuh is grabbing correctly all the data I included into the <order>tag.

[Lucio Donda]

The thing is that the part you must be parsing in the decoder should be added to the field you hace added also on the out_log

I have checked on my side and after the change on the ossec.conf :

  <localfile>
    <log_format>syslog</log_format>
    <location>/home/vagrant/lucho.txt</location>

    <out_format>$(timestamp) MicrosoftExchange: $(log)</out_format>
  </localfile>

I did an echo of the message just to simulate the incomming event:

echo "2024-05-09T00:00:19.344Z,server-name\SMTP 25,08DBBB7EF9630D76,0,192.168.56.14:192.168.56.4:55208,dasda,sadasda," >> /home/vagrant/lucho.txt

logs on archives.log (I enable logall on the ossec.conf also):

2024 May 14 17:06:12 kinetic->/home/vagrant/lucho.txt May 14 17:06:12 MicrosoftExchange: 2024-05-09T00:00:19.344Z,server-name\SMTP 25,08DBBB7EF9630D76,0,192.168.56.14:192.168.56.4:55208,dasda,sadasda,

tested with the logtest :

May 14 17:06:12 MicrosoftExchange: 2024-05-09T00:00:19.344Z,server-name\SMTP 25,08DBBB7EF9630D76,0,192.168.56.14:192.168.56.4:55208,dasda,sadasda,

**Phase 1: Completed pre-decoding.
full event: 'May 14 17:06:12 MicrosoftExchange: 2024-05-09T00:00:19.344Z,server-name\SMTP 25,08DBBB7EF9630D76,0,192.168.56.14:192.168.56.4:55208,dasda,sadasda,'
timestamp: 'May 14 17:06:12'
hostname: 'MicrosoftExchange:'
program_name: 'MicrosoftExchange'

**Phase 2: Completed decoding.
name: 'custom_mysql'

Being my decoder on local_decoder.xml :

<decoder name="custom_mysql">
    <program_name>MicrosoftExchange</program_name>

    <regex type="pcre2">(server-name\\SMTP \d{2,3}),([A-z0-9]+),(\d+),(\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}:587),(\d{1,3}.\d{1,3}.\d{1,3}.\d{1,3}:\d+),(\W*),(.*),(.*)</regex>
    <order>connector-id,session-id,sequence-number,local-endpoint,remote-endpoint,event,data,context</order>
</decoder>

Maybe you can replicate something like it. let me know!

[Gennaro Losappio]

I works indeed. This is what I get:

**Messages: WARNING: (7605): It is not possible to overwrite 'if_matched_sid' value in rule '31101'. The original value is retained. INFO: (7202): Session initialized with token '2b482bc9' **Phase 1: Completed pre-decoding. full event: 'May 14 17:06:12 MicrosoftExchange: 2024-05-09T00:00:19.344Z,server-name\SMTP 25,08DBBB7EF9630D76,0,192.168.56.14:192.168.56.4:55208,dasda,sadasda,' timestamp: 'May 14 17:06:12' hostname: 'MicrosoftExchange:' program_name: 'MicrosoftExchange' **Phase 2: Completed decoding. No decoder matched.

Thank you Lucio