Add logging to plugin

[dkreuer]

This PR adds logging ability and log entries for request analyzing.

The configuration does not change since there already is a LogLevel config .. currently in use are

• DEBUG - shows details of processing
• INFO - shows outcome of analyzing and blocking
• ERROR - shows only errors in processing

This PR resolves #1 .

Example output in log (plugin logLevel debug, output contains access log from traefik too):

traefik-1  | timestamp="2024-01-12T13:54:59Z" level=debug message="Setting log level to DEBUG" plugin="JUIT Fail2Ban" 
traefik-1  | timestamp="2024-01-12T13:55:05Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" 
traefik-1  | timestamp="2024-01-12T13:55:05Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 
traefik-1  | timestamp="2024-01-12T13:55:05Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 
traefik-1  | timestamp="2024-01-12T13:55:05Z" level=debug message="Response Status Code matched rule. Incrementing." plugin="JUIT Fail2Ban" statusCodeRegexp=^(200)$ responseStatusCode=200 
traefik-1  | 192.168.181.1 - - [12/Jan/2024:13:55:05 +0000] "GET / HTTP/1.1" 200 717 "-" "-" 1 "whoami@docker" "http://192.168.181.2:80" 7ms
traefik-1  | timestamp="2024-01-12T13:55:11Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" 
traefik-1  | timestamp="2024-01-12T13:55:11Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 
traefik-1  | timestamp="2024-01-12T13:55:11Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 
traefik-1  | timestamp="2024-01-12T13:55:11Z" level=debug message="Response Status Code matched rule. Incrementing." plugin="JUIT Fail2Ban" statusCodeRegexp=^(200)$ responseStatusCode=200 
traefik-1  | 192.168.181.1 - - [12/Jan/2024:13:55:11 +0000] "GET / HTTP/1.1" 200 717 "-" "-" 2 "whoami@docker" "http://192.168.181.2:80" 3ms
traefik-1  | timestamp="2024-01-12T13:55:11Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" 
traefik-1  | timestamp="2024-01-12T13:55:11Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 
traefik-1  | timestamp="2024-01-12T13:55:11Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 
traefik-1  | timestamp="2024-01-12T13:55:11Z" level=debug message="Response Status Code matched rule. Incrementing." plugin="JUIT Fail2Ban" statusCodeRegexp=^(200)$ responseStatusCode=200 
traefik-1  | 192.168.181.1 - - [12/Jan/2024:13:55:11 +0000] "GET / HTTP/1.1" 200 717 "-" "-" 3 "whoami@docker" "http://192.168.181.2:80" 3ms
traefik-1  | timestamp="2024-01-12T13:55:12Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" 
traefik-1  | timestamp="2024-01-12T13:55:12Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 
traefik-1  | timestamp="2024-01-12T13:55:12Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 
traefik-1  | timestamp="2024-01-12T13:55:12Z" level=debug message="Response Status Code matched rule. Incrementing." plugin="JUIT Fail2Ban" statusCodeRegexp=^(200)$ responseStatusCode=200 
traefik-1  | 192.168.181.1 - - [12/Jan/2024:13:55:12 +0000] "GET / HTTP/1.1" 200 717 "-" "-" 4 "whoami@docker" "http://192.168.181.2:80" 3ms
traefik-1  | timestamp="2024-01-12T13:55:13Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" 
traefik-1  | timestamp="2024-01-12T13:55:13Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 
traefik-1  | timestamp="2024-01-12T13:55:13Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 
traefik-1  | timestamp="2024-01-12T13:55:13Z" level=info message="Client has been banned." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 maxRetries=4 banTime=5m0s findTime=2m0s 
traefik-1  | timestamp="2024-01-12T13:55:13Z" level=debug message="Client is still banned." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 
traefik-1  | 192.168.181.1 - - [12/Jan/2024:13:55:13 +0000] "GET / HTTP/1.1" 403 0 "-" "-" 5 "whoami@docker" "-" 2ms
traefik-1  | timestamp="2024-01-12T13:55:38Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" 
traefik-1  | timestamp="2024-01-12T13:55:38Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 
traefik-1  | timestamp="2024-01-12T13:55:38Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 
traefik-1  | 192.168.181.1 - - [12/Jan/2024:13:55:38 +0000] "GET / HTTP/1.1" 403 0 "-" "-" 6 "whoami@docker" "-" 2ms
traefik-1  | timestamp="2024-01-12T13:55:38Z" level=debug message="Client is still banned." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 

[ianneub]

This looks great! Thanks @dkreuer !

Only thing I might suggest, and this is very minor, is adding a new field to the log, maybe named action that might report analyzing, incrementing, banned, or still_banned as appropriate. This would give us something to filter on other than the message string. Could run these logs through as metrics too. It's a minor thing, having these logs as is would be a big plus in my book.

Thanks again!

[dkreuer]

You‘re right. Will add sth. like a context/phase whatever ;-)

[dkreuer]

Updated logging with additional fields:

timestamp="2024-01-14T12:17:04Z" level=debug message="Setting log level to DEBUG" plugin="JUIT Fail2Ban" phase=initialize
timestamp="2024-01-14T12:17:59Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" phase=accept_request 
traefik-1  | timestamp="2024-01-14T12:17:59Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 phase=check_request 
traefik-1  | timestamp="2024-01-14T12:17:59Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 phase=check_request 
traefik-1  | timestamp="2024-01-14T12:17:59Z" level=debug message="Response Status Code matched rule. Incrementing." plugin="JUIT Fail2Ban" statusCodeRegexp=^(200)$ responseStatusCode=200 phase=check_response status=denied 
traefik-1  | 192.168.181.1 - - [14/Jan/2024:12:17:59 +0000] "GET / HTTP/1.1" 200 717 "-" "-" 1 "whoami@docker" "http://192.168.181.2:80" 15ms
traefik-1  | timestamp="2024-01-14T12:18:01Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" phase=accept_request 
traefik-1  | timestamp="2024-01-14T12:18:01Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 phase=check_request 
traefik-1  | timestamp="2024-01-14T12:18:01Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 phase=check_request 
traefik-1  | timestamp="2024-01-14T12:18:01Z" level=debug message="Response Status Code matched rule. Incrementing." plugin="JUIT Fail2Ban" statusCodeRegexp=^(200)$ responseStatusCode=200 phase=check_response status=denied 
traefik-1  | 192.168.181.1 - - [14/Jan/2024:12:18:01 +0000] "GET / HTTP/1.1" 200 717 "-" "-" 2 "whoami@docker" "http://192.168.181.2:80" 9ms
traefik-1  | timestamp="2024-01-14T12:18:01Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" phase=accept_request 
traefik-1  | timestamp="2024-01-14T12:18:01Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 phase=check_request 
traefik-1  | timestamp="2024-01-14T12:18:01Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 phase=check_request 
traefik-1  | timestamp="2024-01-14T12:18:01Z" level=debug message="Response Status Code matched rule. Incrementing." plugin="JUIT Fail2Ban" statusCodeRegexp=^(200)$ responseStatusCode=200 phase=check_response status=denied 
traefik-1  | 192.168.181.1 - - [14/Jan/2024:12:18:01 +0000] "GET / HTTP/1.1" 200 717 "-" "-" 3 "whoami@docker" "http://192.168.181.2:80" 5ms
traefik-1  | timestamp="2024-01-14T12:18:02Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" phase=accept_request 
traefik-1  | timestamp="2024-01-14T12:18:02Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 phase=check_request 
traefik-1  | timestamp="2024-01-14T12:18:02Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 phase=check_request 
traefik-1  | timestamp="2024-01-14T12:18:02Z" level=debug message="Response Status Code matched rule. Incrementing." plugin="JUIT Fail2Ban" statusCodeRegexp=^(200)$ responseStatusCode=200 phase=check_response status=denied 
traefik-1  | 192.168.181.1 - - [14/Jan/2024:12:18:02 +0000] "GET / HTTP/1.1" 200 717 "-" "-" 4 "whoami@docker" "http://192.168.181.2:80" 4ms
traefik-1  | timestamp="2024-01-14T12:18:02Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" phase=accept_request 
traefik-1  | timestamp="2024-01-14T12:18:02Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 phase=check_request 
traefik-1  | timestamp="2024-01-14T12:18:02Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 phase=check_request 
traefik-1  | timestamp="2024-01-14T12:18:02Z" level=info message="Client has been banned." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 maxRetries=4 banTime=5m0s findTime=2m0s phase=check_request status=denied 
traefik-1  | timestamp="2024-01-14T12:18:02Z" level=debug message="Client is still banned." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 phase=check_request status=denied 
traefik-1  | 192.168.181.1 - - [14/Jan/2024:12:18:02 +0000] "GET / HTTP/1.1" 403 0 "-" "-" 5 "whoami@docker" "-" 3ms
traefik-1  | timestamp="2024-01-14T12:18:04Z" level=debug message="Handler is enabled. Analyzing request." plugin="JUIT Fail2Ban" phase=accept_request 
traefik-1  | timestamp="2024-01-14T12:18:04Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=::/64 phase=check_request 
traefik-1  | timestamp="2024-01-14T12:18:04Z" level=debug message="Checking if remoteIP is in static allowed Netmask." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 netmask=127.0.0.1/32 phase=check_request 
traefik-1  | 192.168.181.1 - - [14/Jan/2024:12:18:04 +0000] "GET / HTTP/1.1" 403 0 "-" "-" 6 "whoami@docker" "-" 2ms
traefik-1  | timestamp="2024-01-14T12:18:04Z" level=debug message="Client is still banned." plugin="JUIT Fail2Ban" remoteIP=192.168.181.1 phase=check_request status=denied

[fliot]

Super !!!!!!!!!
Congrats.