Event Export (auth_request_finished)
I am trying to implement logging of all failed authentication attempts to catch bruteforce automatically. Currently, I have the following configuration:
event_exporter log { format = json format_args = time-rfc3339 transport = log }
metric auth_fail { filter = event=auth_request_finished and not success=yes exporter = log }
However, in logs I only see events similar to this:
{ "event": "auth_request_finished", "hostname": "cheems", "start_time": "2024-08-04T00:00:04.079723Z", "end_time": "2024-08-04T00:00:12.224906Z", "categories": [ "service:auth", "auth" ], "fields": { "duration": 8145091, "policy_result": "ok", "mechanism": "LOGIN", "transport": "trusted", "service": "smtp", "local_ip": "195.201.247.11", "real_local_ip": "195.201.247.11", "remote_ip": "185.29.xx.xx", "real_remote_ip": "185.29.xx.xx", "original_user": "example@example.com", "user": "example@example.com", "translated_user": "example@example.com" } }
But for me it doesn't look like what is specified in docs1:
Field | Description
error | Set when error happens success | yes, when authentication succeeded policy_penalty | Time of penalty added by policy server policy_result | Values: ok, delayed, refused
Why I don't see neither "success" and "error" field in logs? Also, why policy_result is ok despite I am logging only failed authentication attempts? From postfix I can see that those attempts were actually failed:
Aug 04 00:00:14 cheems postfix/smtpd[2362656]: warning: unknown[185.29.xx.xx]:54330: SASL LOGIN authentication failed: (reason unavailable), sasl_username=example@example.com
-- Send unsolicited bulk mail to carle34@at.encryp.ch
On 04/08/2024 13:17, Serhii via dovecot wrote:
I am trying to implement logging of all failed authentication attempts to catch bruteforce automatically. Currently, I have the following configuration: ...
But for me it doesn't look like what is specified in docs[1]:
Field | Description --- error | Set when error happens success | yes, when authentication succeeded policy_penalty | Time of penalty added by policy server policy_result | Values: ok, delayed, refused
Why I don't see neither "success" and "error" field in logs? Also, why policy_result is ok despite I am logging only failed authentication attempts? From postfix I can see that those attempts were actually failed:
Hi Serhii the way the code currently works is that "success: yes" is the only possible value. When the authentication is not successful the "success" is not present. i.e. there is no "success: no". You're not seeing any "success" values since the code only produces "success: yes" and you've filtered that out. As to why you're not seeing any error, my suspicion is that it is unintentional. If I am right about that then the following patch in the function auth_request_fail_with_reply(...) could solve it. It now logs error: authentication failed. --- dovecot-2.3.21-orig/src/auth/auth-request.c 2023-09-14 15:17:46.000000000 +0200 +++ dovecot-2.3.21/src/auth/auth-request.c 2024-08-04 14:43:03.837000812 +0200 @@ -303,7 +303,7 @@ stats = auth_request_stats_get(request); stats->auth_failure_count++; } - + request->failed = TRUE; auth_request_set_state(request, AUTH_REQUEST_STATE_FINISHED); auth_request_refresh_last_access(request); auth_request_log_finished(request); The need for something like this also seems to be warranted by the fact that internal failures on authentication only get reported by the event logging if request->failed is set and I couldn't see anywhere that happens. With the above patch these will also now be logged if there is a call to the function auth_request_internal_failure(...) I also think that the above patch may not deal with all the cases where there is an internal failure in authentication, but those are a bit harder to test. There may still be some cases where there is neither a success or error, and those cases should still be treated as failures or subject to further patching. John
On 8/4/24 13:25, John Fawcett via dovecot wrote:
On 04/08/2024 13:17, Serhii via dovecot wrote:
I am trying to implement logging of all failed authentication attempts to catch bruteforce automatically. Currently, I have the following configuration: ...
But for me it doesn't look like what is specified in docs[1]:
Field | Description --- error | Set when error happens success | yes, when authentication succeeded policy_penalty | Time of penalty added by policy server policy_result | Values: ok, delayed, refused
Why I don't see neither "success" and "error" field in logs? Also, why policy_result is ok despite I am logging only failed authentication attempts? From postfix I can see that those attempts were actually failed:
Hi Serhii
the way the code currently works is that "success: yes" is the only possible value. When the authentication is not successful the "success" is not present. i.e. there is no "success: no".
You're not seeing any "success" values since the code only produces "success: yes" and you've filtered that out.
As to why you're not seeing any error, my suspicion is that it is unintentional. If I am right about that then the following patch in the function auth_request_fail_with_reply(...) could solve it. It now logs error: authentication failed.
--- dovecot-2.3.21-orig/src/auth/auth-request.c 2023-09-14 15:17:46.000000000 +0200 +++ dovecot-2.3.21/src/auth/auth-request.c 2024-08-04 14:43:03.837000812 +0200 @@ -303,7 +303,7 @@ stats = auth_request_stats_get(request); stats->auth_failure_count++; } - + request->failed = TRUE; auth_request_set_state(request, AUTH_REQUEST_STATE_FINISHED); auth_request_refresh_last_access(request); auth_request_log_finished(request);
For my usecase it solves the problem, thank you! So, with this patch I can see both cases when user was not found: { "event": "auth_request_finished", "hostname": "cheems", "start_time": "2024-08-10T07:20:02.159360Z", "end_time": "2024-08-10T07:20:48.092606Z", "categories": [ "service:auth", "auth" ], "fields": { "duration": 45933175, "error": "authentication failed", "mechanism": "LOGIN", "transport": "trusted", "service": "smtp", "local_ip": "2a01:4f8:231:76a::2", "real_local_ip": "2a01:4f8:231:76a::2", "remote_ip": "redacted", "real_remote_ip": "redacted", "original_user": "no-such-user@example.com", "user": "" } } and when password is not correct: { "event": "auth_request_finished", "hostname": "cheems", "start_time": "2024-08-10T07:21:31.952608Z", "end_time": "2024-08-10T07:21:47.588093Z", "categories": [ "service:auth", "auth" ], "fields": { "duration": 15635410, "error": "authentication failed", "policy_result": "ok", "mechanism": "LOGIN", "transport": "trusted", "service": "smtp", "local_ip": "2a01:4f8:231:76a::2", "real_local_ip": "2a01:4f8:231:76a::2", "remote_ip": "redacted", "real_remote_ip": "redacted", "original_user": "user@example.com", "user": "user@example.com", "translated_user": "user@example.com" } } Error message is not that descriptive, but it is way better than it was originally.
The need for something like this also seems to be warranted by the fact that internal failures on authentication only get reported by the event logging if request->failed is set and I couldn't see anywhere that happens. With the above patch these will also now be logged if there is a call to the function auth_request_internal_failure(...)
I also think that the above patch may not deal with all the cases where there is an internal failure in authentication, but those are a bit harder to test. There may still be some cases where there is neither a success or error, and those cases should still be treated as failures or subject to further patching.
John
-- Send unsolicited bulk mail to carle34@at.encryp.ch
participants (2)
-
John Fawcett
-
Serhii