IPBan bans IPs false positiv

[dtx-GB]

Hi,

I'm just starting with IPBan and I'm glad that I found this.

The issue:
IPBan works fine, but every time I get a request from the web server the FailedLogin counter counted up by 1. Even if I've already be logged in.

I'm using nginx thus I had to update the ipban.conf.
Here are my insertions.

  <LogFile>
    <Source>nginx</Source>
    <PathAndMask>
      E:\nginx\logs\mobil-access.log
    </PathAndMask>
    <FailedLoginRegex>
      <![CDATA[
        ^(?<ipaddress>[0-9]*\.[0-9]*\.[0-9]*\.[0-9]*) - - (\[(?<dateandtime>.*)\]) ("(?<refferer>.*)") (?<statuscode>[0-9]{3}) (?<bytessent>[0-9]{3}) ("(?<url>.*)") ("(?<useragent>.*)")
      ]]>
    </FailedLoginRegex>
    <FailedLoginRegexTimestampFormat>dd/MMM/yyyy:HH:mm:ss zzzz</FailedLoginRegexTimestampFormat>
    <PlatformRegex>Windows|Linux</PlatformRegex>
    <PingInterval>10000</PingInterval>
    <MaxFileSize>16777216</MaxFileSize>
    <FailedLoginThreshold>0</FailedLoginThreshold>

	<!-- Optional, set a log level for failed logins - must match exactly (case sensitive) one of the following:
	Trace, Debug, Info, Warn, Error, Critical -->
	<FailedLoginLogLevel>Debug</FailedLoginLogLevel>

  </LogFile>

The IPBan.log looks like that

2023-02-11 15:36:20.2536|TRACE|IPBan|Processing log file E:/nginx/logs/mobil-access.log, len = 387733, pos = 386658
2023-02-11 15:36:20.2536|DEBUG|IPBan|Parsing log file text
94.134.91.253 - - [11/Feb/2023:15:36:10 +0100] "GET /path/app/?rq_AppGuid=F2016860E784C6E7562512D7A3F80C7C7CE99127&rq_TargetPageGuid=360FD0F2931F8CD0EB5BC7470ACBC68494C60A2F&qs_link=A40241E6B8AB872CD5276CA9C120C86A37B8CD83&qs_template=stage&rq_xhr=31 HTTP/2.0" 200 14686 "https://my-url.de/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/108.0.0.0 Safari/537.36 OPR/94.0.0.0"
94.134.91.253 - - [11/Feb/2023:15:36:10 +0100] "POST /?rq_pageGuid=33363046443046323933314638434430454235424337343730414342433638343934433630413246&rq_appGuid=46323031363836304537383443364537353632353132443741334638304337433743453939313237&rq_recordID=2D31&rq_pageName=4D65696E2044612D54655820654D61696C73&rq_tableName=43524D5F434F4E5441435453&rq_colName=46554C4C4E414D45&qs_wfEventGuid=6EE1418245086E2D8EA49049D4B087EF04140E60&rq_command=workflow&rq_xhr=31 HTTP/2.0" 200 181 "https://my-url.de/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/108.0.0.0 Safari/537.36 OPR/94.0.0.0"
...
2023-02-11 15:36:20.2536|DEBUG|IPBan|Log file found match, ip: 94.134.91.253, user: , source: nginx, count: 1, type: FailedLogin
2023-02-11 15:36:20.8786|TRACE|IPBan|Watched file E:/nginx/logs/access.log length has not changed
2023-02-11 15:36:26.0964|TRACE|IPBan|CycleTimerElapsed
2023-02-11 15:36:26.0964|TRACE|IPBan|Ignoring log file path E:/nginx/logs/mobil-access.log, regex: Windows|Linux, no matching file: False, platform match: True
2023-02-11 15:36:26.0964|TRACE|IPBan|Processing log event IP: 94.134.91.253, UserName: , Source: nginx, Count: 1, Type: FailedLogin, Timestamp: 11.02.2023 14:36:20...
2023-02-11 15:36:26.0964|DEBUG|IPBan|0 pending failed logins
2023-02-11 15:36:26.0964|DEBUG|IPBan|Login failure: 94.134.91.253, , nginx, 10,
2023-02-11 15:36:26.0964|DEBUG|IPBan|Failed login count 10 <= ban count 30

As fare as I can see, there is no failed login in the nginx log file.

94.134.91.253 - - [11/Feb/2023:13:59:23 +0100] "GET /path/app/?rq_AppGuid=F2016860E784C6E7562512D7A3F80C7C7CE99127&rq_TargetPageGuid=360FD0F2931F8CD0EB5BC7470ACBC68494C60A2F&qs_link=A40241E6B8AB872CD5276CA9C120C86A37B8CD83&qs_template=stage&rq_xhr=31 HTTP/2.0" 200 14688 "https://my-url.de/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/108.0.0.0 Safari/537.36 OPR/94.0.0.0"
94.134.91.253 - - [11/Feb/2023:13:59:24 +0100] "POST /?rq_pageGuid=33363046443046323933314638434430454235424337343730414342433638343934433630413246&rq_appGuid=46323031363836304537383443364537353632353132443741334638304337433743453939313237&rq_recordID=2D31&rq_pageName=4D65696E2044612D54655820654D61696C73&rq_tableName=43524D5F434F4E5441435453&rq_colName=46554C4C4E414D45&qs_wfEventGuid=6EE1418245086E2D8EA49049D4B087EF04140E60&rq_command=workflow&rq_xhr=31 HTTP/2.0" 200 181 "https://my-url.de/" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/108.0.0.0 Safari/537.36 OPR/94.0.0.0"

Has someone an Idea there the issue comes from?

Thanks for your help.

[dtx-GB]

Hi,

I'm a bit further.

The issue depends on the JavaScript function triggerUserWorkflowEvent() of the framework I use.
This function allows me to start an groovy script from the web site.
The function returns a "true" or "false". In my case a "true".

Since this is maybe an JavsScript issue I checked this behavior with Chrome and Opera. Both with the same result.

Because I'm not sure, if this is an IPBan issue, I will also write an ticket to the framework-developer. Maybe it would be helpful for the developer to know, what exactly you are testing for to indicate a FailedLogin.

If is helpful I could post same tracking data.

Thanks for your help again.

[jjxtra]

Ipban only parses log files, so if something is in the log that should t be or the parsing is picking up something it shouldn't then I can help with that.

[dtx-GB]

Hi jjxtra,

thank you for your answer. I checked again the parsing regex. There are 7 parts, which looks fine to me.

1. IP-Address
2. date and time
3. the refferer
4. the status code
5. the amount of the bytes
6. the url
7. and the useragent

^(?<ipaddress>[0-9]*\.[0-9]*\.[0-9]*\.[0-9]*) - - (\[(?<dateandtime>.*)\]) ("(?<refferer>.*)") (?<statuscode>[0-9]{3}) (?<bytessent>[0-9]{3}) ("(?<url>.*)") ("(?<useragent>.*)")

Thus, in the log file are only 2 entries belonging to the IP and timestamp, 1 Get and 1 Post.

192.168.0.24 - - [13/Feb/2023:09:45:01 +0100] "GET /path/app/?rq_AppGuid=0CAC13D31354DF1BD02C3728AF87511985F0F2E0&rq_TargetPageGuid=13263AE95D1BE10DBCCC43BD7E8F1296F4A91962&qs_link=56C9B4A64EC1515B6FAA2A966AD5D94436AAE99F&qs_template=stage&rq_xhr=31 HTTP/2.0" 200 3392 "https://my-url.de/path/app/?rq_AppGuid=F2016860E784C6E7562512D7A3F80C7C7CE99127&rq_TargetPageGuid=8A2E9CF706BD9A89BC1E92953443EA5A04905C03&rq_MenuGuid=A960403379FA3E9B25486D7355D0C2A85CA28953" "Mozilla/5.0 (Windows NT 6.2; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/108.0.0.0 Safari/537.36 OPR/94.0.0.0"
192.168.0.24 - - [13/Feb/2023:09:45:02 +0100] "POST /?qs_wfEventGuid=C914A5BEA802F8CAAC0F41EC9157C724B62D2F42&rq_command=workflow&rq_xhr=31 HTTP/2.0" 200 181 "https://my-url.de/path/app/?rq_AppGuid=F2016860E784C6E7562512D7A3F80C7C7CE99127&rq_TargetPageGuid=8A2E9CF706BD9A89BC1E92953443EA5A04905C03&rq_MenuGuid=A960403379FA3E9B25486D7355D0C2A85CA28953" "Mozilla/5.0 (Windows NT 6.2; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/108.0.0.0 Safari/537.36 OPR/94.0.0.0"

I did't I know which part is responsible for indicating the FailsLogin, but I assume that is the refferer-part of POST, since this contains the request of the workflow (qs_wfEventGuid).

I know all the meanings of the parameters, except the last one (&rq_xhr=31). All parameters make sense to me. With the GET command the page is requested and the POST command is executed because of the onload-event.

Thus, do you have an Idea?

Thank you for your help!

[jjxtra]

Have you tried debugging this in https://regex101.com? Make sure to set it to use C#/.NET expressions and the regex options to ignore case and multiline.

[dtx-GB]

Hi jjxtra,

Yes, I used https://rexex101.com for debugging, but I had a misconception. I tried to find a valid log entry and not an invalid one.
Sorry!

The 2nd point was that I had the wrong flavor, PHP instead of C#/.Net.

And the 3rd point was that the only indicator of wrong login is the $body_bytes_sent. I assumed there was something unique in the refferer.

Thanks a lot for your help!