Author |
|
abrauer-cpt
Joined: 08 Apr 2022 Posts: 11 Location: Germany
|
Posted: Tue 12 Apr '22 16:28 Post subject: mlogc.exe (failed match regex) after update 2.9.5 (solved) |
|
|
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
|
|
Back to top |
|
abrauer-cpt
Joined: 08 Apr 2022 Posts: 11 Location: Germany
|
Posted: Thu 21 Apr '22 9:38 Post subject: |
|
|
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
|
Posted: Thu 21 Apr '22 23:03 Post subject: |
|
|
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
|
Posted: Tue 10 May '22 14:42 Post subject: |
|
|
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
|
Posted: Thu 12 May '22 12:08 Post subject: |
|
|
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
|
Posted: Thu 12 May '22 12:25 Post subject: |
|
|
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
|
Posted: Thu 12 May '22 13:23 Post subject: |
|
|
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
|
Posted: Thu 12 May '22 16:19 Post subject: |
|
|
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
|
Posted: Tue 17 May '22 13:22 Post subject: |
|
|
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: 3092 Location: Hilversum, NL, EU
|
|
Back to top |
|
abrauer-cpt
Joined: 08 Apr 2022 Posts: 11 Location: Germany
|
Posted: Mon 30 May '22 10:27 Post subject: |
|
|
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: 3092 Location: Hilversum, NL, EU
|
Posted: Wed 01 Jun '22 17:12 Post subject: |
|
|
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
|
Posted: Thu 02 Jun '22 9:03 Post subject: |
|
|
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: 3092 Location: Hilversum, NL, EU
|
Posted: Wed 29 Jun '22 11:50 Post subject: |
|
|
Mod_security 2.9.5 Win64 updated with the fix for mlogc, |
|
Back to top |
|