logo
Apache Lounge
Webmasters

 

About Forum Index Downloads Search Register Log in RSS X


Keep Server Online

If you find the Apache Lounge, the downloads and overall help useful, please express your satisfaction with a donation.

or

Bitcoin

A donation makes a contribution towards the costs, the time and effort that's going in this site and building.

Thank You! Steffen

Your donations will help to keep this site alive and well, and continuing building binaries. Apache Lounge is not sponsored.
Post new topic   Forum Index -> Third-party Modules View previous topic :: View next topic
Reply to topic   Topic: mlogc.exe (failed match regex) after update 2.9.5 (solved)
Author
abrauer-cpt



Joined: 08 Apr 2022
Posts: 11
Location: Germany

PostPosted: Tue 12 Apr '22 16:28    Post subject: mlogc.exe (failed match regex) after update 2.9.5 (solved) Reply with quote

After update of apache and mod_security mlogc.exe failed to send log-entries.

Update from:
Windows Server 2016
Apache 2.4.49 (x64)
mod_security 2.9.3 (x64)

Update to:
Apache 2.4.53 (x64)
mod_security 2.9.5 (x64)
libapr-1-fix

No cofiguration changes were made.

Error (mlogc-error.log):
Invalid entry (failed to match regex)

Before update everything was fine without errors.
If i downgrade mlogc went back to normal work.

Did anyone had the same error or better a solution?
Back to top
tangent
Moderator


Joined: 16 Aug 2020
Posts: 348
Location: UK

PostPosted: Tue 12 Apr '22 20:35    Post subject: Reply with quote

Apache httpd release 2.4.53 is now built with PCRE2 - see https://www.apachelounge.com/viewtopic.php?t=8861&highlight=pcre2

However, Steffen points out here in this earlier post (https://www.apachelounge.com/viewtopic.php?t=8843) that mod_security is built with the old PCRE. So for now you need to leave a copy of the old pcre.dll in the bin directory.
Back to top
abrauer-cpt



Joined: 08 Apr 2022
Posts: 11
Location: Germany

PostPosted: Thu 21 Apr '22 9:38    Post subject: Reply with quote

Hello tangent,

thank you for your reply.

In my update-test I had left the pcre.dll in the /bin folder.

Is there any other configuration I have to do?
Back to top
tangent
Moderator


Joined: 16 Aug 2020
Posts: 348
Location: UK

PostPosted: Thu 21 Apr '22 23:03    Post subject: Reply with quote

If you turn up the debug level do the logs give you any more clues over which regex construct is failing?

At this point I'd suspect a subtle change in mod_security functionality, so my next step would be to verify this by trying 2.9.3 with the later Apache release.

You might need to refine your mod_security configuration.
Back to top
abrauer-cpt



Joined: 08 Apr 2022
Posts: 11
Location: Germany

PostPosted: Tue 10 May '22 14:42    Post subject: Reply with quote

Sorry for my late reply, i was on vacation.

The debug logs don't give me more clues, or i don't see them. (with high debug level the logs are very large)

I tested mod_security with later Apache release:
Apache 2.4.53 (x64)
mod_security 2.9.3 (x64) (no Update)
No Configuration-Change

Runs without error.

I'm trying some more tests.
Back to top
abrauer-cpt



Joined: 08 Apr 2022
Posts: 11
Location: Germany

PostPosted: Thu 12 May '22 12:08    Post subject: Reply with quote

Ok, i have done some tests.
I can reproduce the error if i simple change the mod_security2.so and mlogc.exe from 2.9.3 to 2.9.5

The only difference i see, is the part after "Processing entry."
Version 2.9.5: "Invalid entry (failed to match regex)"
Version 2.9.3: "Regular expression matched."

Does anyone know what could trigger this error.

mlogc-error.log (debug)

Version 2.9.5
Code:
[Thu May 12 10:27:08 2022] [3] [1320/0] Configuring ModSecurity Audit Log Collector 2.9.5.
[Thu May 12 10:27:08 2022] [3] [1320/0] Delaying execution for 5000ms.
[Thu May 12 10:27:11 2022] [4] [4888/0] Continuing execution after 5000ms delay.
[Thu May 12 10:27:11 2022] [5] [4888/0] CollectorRoot=c:/Apache24/logs/mlogc/log
[Thu May 12 10:27:11 2022] [5] [4888/0] ErrorLog=c:/Apache24/logs/mlogc/log/mlogc-error.log
[Thu May 12 10:27:11 2022] [5] [4888/0] ErrorLogLevel=5
[Thu May 12 10:27:11 2022] [5] [4888/0] StartupDelay=5000
[Thu May 12 10:27:11 2022] [5] [4888/0] TLSProtocol=1
[Thu May 12 10:27:11 2022] [5] [4888/0] cURL version=7.83.0
[Thu May 12 10:27:11 2022] [5] [4888/0] CheckpointInterval=15
[Thu May 12 10:27:11 2022] [5] [4888/0] InsecureNoCheckCert=1
[Thu May 12 10:27:11 2022] [5] [4888/0] QueuePath=c:/Apache24/logs/mlogc/log/mlogc-queue.log
[Thu May 12 10:27:11 2022] [5] [4888/0] LockFile=c:/Apache24/logs/mlogc/log/mlogc.lck
[Thu May 12 10:27:11 2022] [5] [4888/0] ServerErrorTimeout=60
[Thu May 12 10:27:11 2022] [5] [4888/0] TransactionDelay=50
[Thu May 12 10:27:11 2022] [5] [4888/0] TransactionLog=c:/Apache24/logs/mlogc/log/mlogc-transaction.log
[Thu May 12 10:27:11 2022] [5] [4888/0] MaxConnections=10
[Thu May 12 10:27:11 2022] [5] [4888/0] MaxWorkerRequests=1000
[Thu May 12 10:27:11 2022] [5] [4888/0] LogStorageDir=C:/Apache24/logs/mlogc/audit
[Thu May 12 10:27:11 2022] [5] [4888/0] ConsoleURI=http://xxx.xxx.xxx.xxx:8080/AuditConsole/rpc/auditLogReceiver
[Thu May 12 10:27:11 2022] [5] [4888/0] SensorUsername=xxxxxxxxxx
[Thu May 12 10:27:11 2022] [5] [4888/0] SensorPassword=xxxxxxxxxx
[Thu May 12 10:27:11 2022] [5] [4888/0] KeepEntries=0

[Thu May 12 10:27:55 2022] [5] [1320/0] Read 273 bytes from pipe: `localhost ::1 - - [12/May/2022:10:27:55.867925 +0200] \"GET /server-status?resource=js HTTP/1.1\" 200 57913 \"-\" \"-\" YnzFC27a8n3ZIzLvOD77qwAAAf0 \"-\" /Administrator/20220512/20220512-1027/20220512-102755-YnzFC27a8n3ZIzLvOD77qwAAAf0 0 1244 md5:f81660674d363c13bcf97e3454d93b81 \n'
[Thu May 12 10:27:55 2022] [5] [1320/0] Received audit log entry (count 1 queue 0 workers 0): localhost ::1 - - [12/May/2022:10:27:55.867925 +0200] \"GET /server-status?resource=js HTTP/1.1\" 200 57913 \"-\" \"-\" YnzFC27a8n3ZIzLvOD77qwAAAf0 \"-\" /Administrator/20220512/20220512-1027/20220512-102755-YnzFC27a8n3ZIzLvOD77qwAAAf0 0 1244 md5:f81660674d363c13bcf97e3454d93b81
[Thu May 12 10:27:55 2022] [4] [1320/0] Queue locking thread mutex.
[Thu May 12 10:27:55 2022] [4] [1320/0] Worker creation started.
[Thu May 12 10:27:55 2022] [4] [1320/0] Worker creation completed: 221154c22b0
[Thu May 12 10:27:55 2022] [4] [1320/0] Queue unlocking thread mutex.
[Thu May 12 10:27:55 2022] [4] [1320/0] Processed 1 entries from buffer.
[Thu May 12 10:27:55 2022] [5] [1320/0] Shifted buffer back 260 and offset 0 bytes for next read: `'
[Thu May 12 10:27:55 2022] [5] [1320/0] Internal state: [evnt "0"][curr "0"][next "0"][nbytes "65536"]
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker thread starting.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker fetch locking thread mutex.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker fetch waiting on thread mutex.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker fetch started.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Getting one entry from the queue.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker fetch completed.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker fetch unlocking thread mutex.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Processing entry.
[Thu May 12 10:27:55 2022] [2] [1320/221154c22b0] Invalid entry (failed to match regex): localhost ::1 - - [12/May/2022:10:27:55.867925 +0200] \"GET /server-status?resource=js HTTP/1.1\" 200 57913 \"-\" \"-\" YnzFC27a8n3ZIzLvOD77qwAAAf0 \"-\" /Administrator/20220512/20220512-1027/20220512-102755-YnzFC27a8n3ZIzLvOD77qwAAAf0 0 1244 md5:f81660674d363c13bcf97e3454d93b81
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker processing completed.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker fetch locking thread mutex.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker fetch waiting on thread mutex.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker fetch started.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Removing previous entry from storage.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Getting one entry from the queue.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker fetch unlocking thread mutex.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] No more work for this thread, exiting.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker shutdown locking thread mutex.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker shutdown unlocking thread mutex.
[Thu May 12 10:27:55 2022] [4] [1320/221154c22b0] Worker thread completed.


Version 2.9.3
Code:
[Thu May 12 10:59:17 2022] [3] [11220/0] Configuring ModSecurity Audit Log Collector 2.9.3.
[Thu May 12 10:59:17 2022] [3] [11220/0] Delaying execution for 5000ms.
[Thu May 12 10:59:18 2022] [4] [7100/0] Continuing execution after 5000ms delay.
[Thu May 12 10:59:18 2022] [5] [7100/0] CollectorRoot=c:/Apache24/logs/mlogc/log
[Thu May 12 10:59:18 2022] [5] [7100/0] ErrorLog=c:/Apache24/logs/mlogc/log/mlogc-error.log
[Thu May 12 10:59:18 2022] [5] [7100/0] ErrorLogLevel=5
[Thu May 12 10:59:18 2022] [5] [7100/0] StartupDelay=5000
[Thu May 12 10:59:18 2022] [5] [7100/0] TLSProtocol=1
[Thu May 12 10:59:18 2022] [5] [7100/0] cURL version=7.83.0
[Thu May 12 10:59:18 2022] [5] [7100/0] CheckpointInterval=15
[Thu May 12 10:59:18 2022] [5] [7100/0] InsecureNoCheckCert=1
[Thu May 12 10:59:18 2022] [5] [7100/0] QueuePath=c:/Apache24/logs/mlogc/log/mlogc-queue.log
[Thu May 12 10:59:18 2022] [5] [7100/0] LockFile=c:/Apache24/logs/mlogc/log/mlogc.lck
[Thu May 12 10:59:18 2022] [5] [7100/0] ServerErrorTimeout=60
[Thu May 12 10:59:18 2022] [5] [7100/0] TransactionDelay=50
[Thu May 12 10:59:18 2022] [5] [7100/0] TransactionLog=c:/Apache24/logs/mlogc/log/mlogc-transaction.log
[Thu May 12 10:59:18 2022] [5] [7100/0] MaxConnections=10
[Thu May 12 10:59:18 2022] [5] [7100/0] MaxWorkerRequests=1000
[Thu May 12 10:59:18 2022] [5] [7100/0] LogStorageDir=C:/Apache24/logs/mlogc/audit
[Thu May 12 10:59:18 2022] [5] [7100/0] ConsoleURI=http://xxx.xxx.xxx.xxx:8080/AuditConsole/rpc/auditLogReceiver
[Thu May 12 10:59:18 2022] [5] [7100/0] SensorUsername=xxxxxxxxxx
[Thu May 12 10:59:18 2022] [5] [7100/0] SensorPassword=xxxxxxxxxx
[Thu May 12 10:59:18 2022] [5] [7100/0] KeepEntries=0

[Thu May 12 10:59:43 2022] [5] [11220/0] Read 253 bytes from pipe: `localhost ::1 - - [12/May/2022:10:59:43 +0200] \"GET /server-status HTTP/1.1\" 200 4929 \"-\" \"-\" YnzMf4l7FZcDLwRzdLMrBwAAAf0 \"-\" /apacheservice/20220512/20220512-1059/20220512-105943-YnzMf4l7FZcDLwRzdLMrBwAAAf0 0 6299 md5:325c85f3977cfc3031f259c93697163a \n'
[Thu May 12 10:59:43 2022] [5] [11220/0] Received audit log entry (count 1 queue 0 workers 0): localhost ::1 - - [12/May/2022:10:59:43 +0200] \"GET /server-status HTTP/1.1\" 200 4929 \"-\" \"-\" YnzMf4l7FZcDLwRzdLMrBwAAAf0 \"-\" /apacheservice/20220512/20220512-1059/20220512-105943-YnzMf4l7FZcDLwRzdLMrBwAAAf0 0 6299 md5:325c85f3977cfc3031f259c93697163a
[Thu May 12 10:59:43 2022] [4] [11220/0] Queue locking thread mutex.
[Thu May 12 10:59:43 2022] [4] [11220/0] Worker creation started.
[Thu May 12 10:59:43 2022] [4] [11220/0] Creating thread_pool.
[Thu May 12 10:59:43 2022] [4] [11220/0] Worker creation completed: 2511bc511b8
[Thu May 12 10:59:43 2022] [4] [11220/0] Queue unlocking thread mutex.
[Thu May 12 10:59:43 2022] [4] [11220/0] Processed 1 entries from buffer.
[Thu May 12 10:59:43 2022] [5] [11220/0] Shifted buffer back 253 and offset 0 bytes for next read: `'
[Thu May 12 10:59:43 2022] [5] [11220/0] Internal state: [evnt "0"][curr "0"][next "0"][nbytes "65536"]
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] Worker thread starting.
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] Worker fetch locking thread mutex.
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] Worker fetch started.
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] Getting one entry from the queue.
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] Worker fetch completed.
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] Worker fetch unlocking thread mutex.
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] Processing entry.
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] Regular expression matched.
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] STAT "C:/Apache24/logs/mlogc/audit/apacheservice/20220512/20220512-1059/20220512-105943-YnzMf4l7FZcDLwRzdLMrBwAAAf0" {uid=465616768; gid=0; size=6299; csize=0; atime=0; ctime=0; mtime=0}
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] File found (6299 bytes), activating cURL.
[Thu May 12 10:59:43 2022] [5] [11220/2511bc511b8] CURL: Trying xxx.xxx.xxx.xxx:8080...
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] CURL: Connected to xxx.xxx.xxx.xxx (xxx.xxx.xxx.xxx) port 8080 (#0)
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] CURL: Server auth using Basic with user 'xxxxxxxxxx'
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] CURL: HEADER_OUT PUT /AuditConsole/rpc/auditLogReceiver HTTP/1.1
[Thu May 12 10:59:43 2022] [5] [11220/2511bc511b8] CURL: DATA_OUT --29000000-A--
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] CURL: We are completely uploaded and fine
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] CURL: Mark bundle as not supporting multiuse
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] CURL: HEADER_IN HTTP/1.1 200
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] CURL: HEADER_IN Set-Cookie: JSESSIONID=F3E6278BEA0E09CBEC5288382A9945A1; Path=/AuditConsole; HttpOnly
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] CURL: HEADER_IN Content-Length: 0
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] CURL: HEADER_IN Date: Thu, 12 May 2022 08:59:42 GMT
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] CURL: HEADER_IN
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] CURL: Connection #0 to host xxx.xxx.xxx.xxx left intact
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] Request returned with status "200 ": YnzMf4l7FZcDLwRzdLMrBwAAAf0
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] Removing: C:/Apache24/logs/mlogc/audit/apacheservice/20220512/20220512-1059/20220512-105943-YnzMf4l7FZcDLwRzdLMrBwAAAf0
[Thu May 12 10:59:43 2022] [3] [11220/2511bc511b8] Entry completed (0.017 seconds, 6299 bytes): YnzMf4l7FZcDLwRzdLMrBwAAAf0
[Thu May 12 10:59:43 2022] [4] [11220/2511bc511b8] Sleeping for 50 msec.
Back to top
admin
Site Admin


Joined: 15 Oct 2005
Posts: 692

PostPosted: Thu 12 May '22 12:25    Post subject: Reply with quote

What happens when you use mlogc.exe 2.9.3 with 2.9.5 ?
Back to top
abrauer-cpt



Joined: 08 Apr 2022
Posts: 11
Location: Germany

PostPosted: Thu 12 May '22 13:23    Post subject: Reply with quote

mod_security 2.9.5 with mlogc.exe 2.9.3: same error
Back to top
abrauer-cpt



Joined: 08 Apr 2022
Posts: 11
Location: Germany

PostPosted: Thu 12 May '22 16:19    Post subject: Reply with quote

I think i found the problem.

mlogc.exe includes an regex-pattern to parse the log-lines.

The log-lines between 2.9.3 and 2.9.5 are slightly different. The timestamps are different.
mod_security 2.9.3 timestamp: [12/May/2022:10:59:43 +0200]
mod_security 2.9.5 timestamp: [12/May/2022:10:27:55.867925 +0200]

So the regex-pattern do not match anymore.

I posted this potential error on github SpiderLabs/ModSecurity.
Back to top
abrauer-cpt



Joined: 08 Apr 2022
Posts: 11
Location: Germany

PostPosted: Tue 17 May '22 13:22    Post subject: Reply with quote

Info:
The "new" timestamp format was added in mod_security 2.9.4 with issue #2095 but no one changed the regex pattern in mlogc.
Back to top
Steffen
Moderator


Joined: 15 Oct 2005
Posts: 3094
Location: Hilversum, NL, EU

PostPosted: Sat 28 May '22 9:30    Post subject: Reply with quote

The log timestamp fix is committted:

https://github.com/SpiderLabs/ModSecurity/pull/2749/commits/f71498ceff32c37228dd20a108f26078dee72885

Please test:

Removed


Last edited by Steffen on Wed 01 Jun '22 17:13; edited 1 time in total
Back to top
abrauer-cpt



Joined: 08 Apr 2022
Posts: 11
Location: Germany

PostPosted: Mon 30 May '22 10:27    Post subject: Reply with quote

Hello Steffen,

i tested this patch and found cases with negative values within the timestamp.
In this cases the regex-pattern failed.

[30/May/2022:09:27:45.-867925 +0200]

We should add something like "-?" to catch this cases.
Back to top
Steffen
Moderator


Joined: 15 Oct 2005
Posts: 3094
Location: Hilversum, NL, EU

PostPosted: Wed 01 Jun '22 17:12    Post subject: Reply with quote

New fix : negative usec on log line when data type long is 32b, see https://github.com/SpiderLabs/ModSecurity/pull/2753


Test at: Download removed


Last edited by Steffen on Wed 29 Jun '22 11:52; edited 2 times in total
Back to top
abrauer-cpt



Joined: 08 Apr 2022
Posts: 11
Location: Germany

PostPosted: Thu 02 Jun '22 9:03    Post subject: Reply with quote

Many thanks Steffen,

I tested this patch in our environment and it works without errors. I have an eye on it in the next days.
Back to top
Steffen
Moderator


Joined: 15 Oct 2005
Posts: 3094
Location: Hilversum, NL, EU

PostPosted: Wed 29 Jun '22 11:50    Post subject: Reply with quote

Mod_security 2.9.5 Win64 updated with the fix for mlogc,
Back to top


Reply to topic   Topic: mlogc.exe (failed match regex) after update 2.9.5 (solved) View previous topic :: View next topic
Post new topic   Forum Index -> Third-party Modules