Merge #2818

2818: Improve auth-related logging r=mergify[bot] a=nextgens

## What type of PR?

enhancement

## What does this PR do?

Improve auth-related logging

### Related issue(s)
- closes #2803 

## Prerequisites
Before we can consider review and merge, please make sure the following list is done and checked.
If an entry in not applicable, you can check it or remove it from the list.

- [ ] In case of feature or enhancement: documentation updated accordingly
- [x] Unless it's docs or a minor change: add [changelog](https://mailu.io/master/contributors/workflow.html#changelog) entry file.


Co-authored-by: Florent Daigniere <nextgens@freenetproject.org>
Co-authored-by: Florent Daigniere <nextgens@users.noreply.github.com>

core/admin/mailu/__init__.py

@@ -12,8 +12,11 @@ import hmac
 
 class NoPingFilter(logging.Filter):
     def filter(self, record):
-        if not (record.args['{host}i'] == 'localhost' and record.args['r'] == 'GET /ping HTTP/1.1'):
+        if (record.args['{host}i'] == 'localhost' and record.args['r'] == 'GET /ping HTTP/1.1'):
-            return True
+            return False
+        if record.args['r'].endswith(' /internal/rspamd/local_domains HTTP/1.1'):
+            return False
+        return True
 
 class Logger(glogging.Logger):
     def setup(self, cfg):
@@ -46,6 +49,7 @@ def create_app_from_config(config):
     app.device_cookie_key = hmac.new(bytearray(app.secret_key, 'utf-8'), bytearray('DEVICE_COOKIE_KEY', 'utf-8'), 'sha256').digest()
     app.temp_token_key = hmac.new(bytearray(app.secret_key, 'utf-8'), bytearray('WEBMAIL_TEMP_TOKEN_KEY', 'utf-8'), 'sha256').digest()
     app.srs_key = hmac.new(bytearray(app.secret_key, 'utf-8'), bytearray('SRS_KEY', 'utf-8'), 'sha256').digest()
+    app.truncated_pw_key = hmac.new(bytearray(app.secret_key, 'utf-8'), bytearray('TRUNCATED_PW_KEY', 'utf-8'), 'sha256').digest()
 
     # Initialize list of translations
     app.config.translations = {
@@ -63,6 +67,7 @@ def create_app_from_config(config):
         debug.profiler.init_app(app)
     if assets := app.config.get('DEBUG_ASSETS'):
         app.static_folder = assets
+    app.logger.setLevel(app.config.get('LOG_LEVEL'))
 
     # Inject the default variables in the Jinja parser
     # TODO: move this to blueprints when needed

core/admin/mailu/configuration.py

@@ -75,7 +75,7 @@ DEFAULT_CONFIG = {
     'API': False,
     'WEB_API': '/api',
     'API_TOKEN': None,
-    'LOG_LEVEL': 'WARNING',
+    'LOG_LEVEL': 'INFO',
     'SESSION_KEY_BITS': 128,
     'SESSION_TIMEOUT': 3600,
     'PERMANENT_SESSION_LIFETIME': 30*24*3600,

core/admin/mailu/internal/nginx.py

@@ -28,23 +28,26 @@ STATUSES = {
 
 WEBMAIL_PORTS = ['14190', '10143', '10025']
 
-def check_credentials(user, password, ip, protocol=None, auth_port=None):
+def check_credentials(user, password, ip, protocol=None, auth_port=None, source_port=None):
     if not user or not user.enabled or (protocol == "imap" and not user.enable_imap and not auth_port in WEBMAIL_PORTS) or (protocol == "pop3" and not user.enable_pop):
+        app.logger.info(f'Login attempt for: {user}/{protocol}/{auth_port} from: {ip}/{source_port}: failed: account disabled')
         return False
-    is_ok = False
     # webmails
     if auth_port in WEBMAIL_PORTS and password.startswith('token-'):
         if utils.verify_temp_token(user.get_id(), password):
-            is_ok = True
+            app.logger.debug(f'Login attempt for: {user}/{protocol}/{auth_port} from: {ip}/{source_port}: success: webmail-token')
-    if not is_ok and utils.is_app_token(password):
+            return True
+    if utils.is_app_token(password):
         for token in user.tokens:
             if (token.check_password(password) and
                 (not token.ip or token.ip == ip)):
-                    is_ok = True
+                    app.logger.info(f'Login attempt for: {user}/{protocol}/{auth_port} from: {ip}/{source_port}: success: token-{token.id}: {token.comment or ""!r}')
-                    break
+                    return True
-    if not is_ok and user.check_password(password):
+    if user.check_password(password):
-        is_ok = True
+        app.logger.info(f'Login attempt for: {user}/{protocol}/{auth_port} from: {ip}/{source_port}: success: password')
-    return is_ok
+        return True
+    app.logger.info(f'Login attempt for: {user}/{protocol}/{auth_port} from: {ip}/{source_port}: failed: badauth: {utils.truncated_pw_hash(password)}')
+    return False
 
 def handle_authentication(headers):
     """ Handle an HTTP nginx authentication request
@@ -101,7 +104,7 @@ def handle_authentication(headers):
             else:
                 is_valid_user = user is not None
                 ip = urllib.parse.unquote(headers["Client-Ip"])
-                if check_credentials(user, password, ip, protocol, headers["Auth-Port"]):
+                if check_credentials(user, password, ip, protocol, headers["Auth-Port"], headers['Client-Port']):
                     server, port = get_server(headers["Auth-Protocol"], True)
                     return {
                         "Auth-Status": "OK",

core/admin/mailu/internal/views/auth.py

@@ -107,7 +107,7 @@ def basic_authentication():
             exc = str(exc).split('\n', 1)[0]
             app.logger.warn(f'Invalid user {user_email!r}: {exc}')
         else:
-            if user is not None and nginx.check_credentials(user, password.decode('utf-8'), client_ip, "web"):
+            if user is not None and nginx.check_credentials(user, password.decode('utf-8'), client_ip, "web", flask.request.headers.get('X-Real-Port', None)):
                 response = flask.Response()
                 response.headers["X-User"] = models.IdnaEmail.process_bind_param(flask_login, user.email, "")
                 utils.limiter.exempt_ip_from_ratelimits(client_ip)

core/admin/mailu/sso/views/base.py

@@ -17,6 +17,7 @@ def login():
         return _proxy()
 
     client_ip = flask.request.headers.get('X-Real-IP', flask.request.remote_addr)
+    client_port = flask.request.headers.get('X-Real-Port', None)
     form = forms.LoginForm()
 
     fields = []
@@ -55,13 +56,13 @@ def login():
             flask_login.login_user(user)
             response = flask.redirect(destination)
             response.set_cookie('rate_limit', utils.limiter.device_cookie(username), max_age=31536000, path=flask.url_for('sso.login'), secure=app.config['SESSION_COOKIE_SECURE'], httponly=True)
-            flask.current_app.logger.info(f'Login succeeded for {username} from {client_ip} pwned={form.pwned.data}.')
+            flask.current_app.logger.info(f'Login attempt for: {username}/sso/{flask.request.headers.get("X-Forwarded-Proto")} from: {client_ip}/{client_port}: success: password: {form.pwned.data}')
             if msg := utils.isBadOrPwned(form):
                 flask.flash(msg, "error")
             return response
         else:
             utils.limiter.rate_limit_user(username, client_ip, device_cookie, device_cookie_username, form.pw.data) if models.User.get(username) else utils.limiter.rate_limit_ip(client_ip, username)
-            flask.current_app.logger.warn(f'Login failed for {username} from {client_ip}.')
+            flask.current_app.logger.info(f'Login attempt for: {username}/sso/{flask.request.headers.get("X-Forwarded-Proto")} from: {client_ip}/{client_port}: failed: badauth: {utils.truncated_pw_hash(form.pw.data)}')
             flask.flash('Wrong e-mail or password', 'error')
     return flask.render_template('login.html', form=form, fields=fields)
 
@@ -96,10 +97,12 @@ def _proxy():
     proxy_ip = flask.request.headers.get('X-Forwarded-By', flask.request.remote_addr)
     ip = ipaddress.ip_address(proxy_ip)
     if not any(ip in cidr for cidr in app.config['PROXY_AUTH_WHITELIST']):
+        flask.current_app.logger.error(f'Login failed by proxy - not on whitelist: from {client_ip} through {flask.request.remote_addr}.')
         return flask.abort(500, '%s is not on PROXY_AUTH_WHITELIST' % proxy_ip)
 
     email = flask.request.headers.get(app.config['PROXY_AUTH_HEADER'])
     if not email:
+        flask.current_app.logger.error(f'Login failed by proxy - no header: from {client_ip} through {flask.request.remote_addr}.')
         return flask.abort(500, 'No %s header' % app.config['PROXY_AUTH_HEADER'])
 
     url = _has_usable_redirect(True) or app.config['WEB_ADMIN']
@@ -108,9 +111,11 @@ def _proxy():
     if user:
         flask.session.regenerate()
         flask_login.login_user(user)
+        flask.current_app.logger.info(f'Login succeeded by proxy created user: {user} from {client_ip} through {flask.request.remote_addr}.')
         return flask.redirect(url)
 
     if not app.config['PROXY_AUTH_CREATE']:
+        flask.current_app.logger.warning(f'Login failed by proxy - does not exist: {user} from {client_ip} through {flask.request.remote_addr}.')
         return flask.abort(500, 'You don\'t exist. Go away! (%s)' % email)
 
     client_ip = flask.request.headers.get('X-Real-IP', flask.request.remote_addr)

core/admin/mailu/ui/templates/token/list.html

@@ -13,10 +13,11 @@
 {%- endblock %}
 
 {%- block content %}
-{%- call macros.table(order='[[1,"asc"]]') %}
+{%- call macros.table(order='[[2,"asc"]]') %}
 <thead>
   <tr>
     <th data-orderable="false">{% trans %}Actions{% endtrans %}</th>
+    <th>{% trans %}ID{% endtrans %}</th>
     <th>{% trans %}Comment{% endtrans %}</th>
     <th>{% trans %}Authorized IP{% endtrans %}</th>
     <th>{% trans %}Created{% endtrans %}</th>
@@ -29,6 +30,7 @@
     <td>
       <a href="{{ url_for('.token_delete', token_id=token.id) }}" title="{% trans %}Delete{% endtrans %}"><i class="fa fa-trash"></i></a>
     </td>
+    <td>{{ token.id }}</td>
     <td>{{ token.comment }}</td>
     <td>{{ token.ip or "any" }}</td>
     <td data-sort="{{ token.created_at or '0000-00-00' }}">{{ token.created_at | format_date }}</td>

core/admin/mailu/utils.py

@@ -532,3 +532,6 @@ def is_app_token(candidate):
     if len(candidate) == 32 and all(c in string.hexdigits[:-6] for c in candidate):
         return True
     return False
+
+def truncated_pw_hash(pw):
+    return hmac.new(app.truncated_pw_key, bytearray(pw, 'utf-8'), 'sha256').hexdigest()[:6]

core/admin/start.py

@@ -52,14 +52,15 @@ def test_DNS():
 test_DNS()
 
 cmdline = [
-	"gunicorn",
+    "gunicorn",
-	"--threads", f"{os.cpu_count()}",
+    "--threads", f"{os.cpu_count()}",
-	# If SUBNET6 is defined, gunicorn must listen on IPv6 as well as IPv4
+    # If SUBNET6 is defined, gunicorn must listen on IPv6 as well as IPv4
-	"-b", f"{'[::]' if os.environ.get('SUBNET6') else ''}:80",
+    "-b", f"{'[::]' if os.environ.get('SUBNET6') else ''}:80",
     "--logger-class mailu.Logger",
+    f"--log-level {os.environ.get('LOG_LEVEL', 'INFO')}",
     "--worker-tmp-dir /dev/shm",
-	"--error-logfile", "-",
+    "--error-logfile", "-",
-	"--preload"
+    "--preload"
 ]
 
 # logging

core/nginx/conf/nginx.conf

@@ -330,6 +330,7 @@ mail {
       protocol smtp;
       smtp_auth plain;
       auth_http_header Auth-Port 10025;
+      auth_http_header Client-Port $remote_port;
     }
 
     # Default IMAP server for the webmail (no encryption, but authentication)
@@ -338,6 +339,7 @@ mail {
       protocol imap;
       smtp_auth plain;
       auth_http_header Auth-Port 10143;
+      auth_http_header Client-Port $remote_port;
       # ensure we talk HAPROXY protocol to the backends
       proxy_protocol on;
     }
@@ -363,6 +365,7 @@ mail {
       protocol smtp;
       smtp_auth none;
       auth_http_header Auth-Port 25;
+      auth_http_header Client-Port $remote_port;
     }
 
     # All other protocols are disabled if TLS is failing
@@ -378,6 +381,7 @@ mail {
       protocol imap;
       imap_auth plain;
       auth_http_header Auth-Port 143;
+      auth_http_header Client-Port $remote_port;
       # ensure we talk HAPROXY protocol to the backends
       proxy_protocol on;
     }
@@ -393,6 +397,7 @@ mail {
       protocol pop3;
       pop3_auth plain;
       auth_http_header Auth-Port 110;
+      auth_http_header Client-Port $remote_port;
       # ensure we talk HAPROXY protocol to the backends
       proxy_protocol on;
     }
@@ -408,6 +413,7 @@ mail {
       protocol smtp;
       smtp_auth plain login;
       auth_http_header Auth-Port 587;
+      auth_http_header Client-Port $remote_port;
     }
 
     {% if TLS %}
@@ -419,6 +425,7 @@ mail {
       protocol smtp;
       smtp_auth plain login;
       auth_http_header Auth-Port 465;
+      auth_http_header Client-Port $remote_port;
     }
 
     server {
@@ -429,6 +436,7 @@ mail {
       protocol imap;
       imap_auth plain;
       auth_http_header Auth-Port 993;
+      auth_http_header Client-Port $remote_port;
       # ensure we talk HAPROXY protocol to the backends
       proxy_protocol on;
     }
@@ -441,6 +449,7 @@ mail {
       protocol pop3;
       pop3_auth plain;
       auth_http_header Auth-Port 995;
+      auth_http_header Client-Port $remote_port;
       # ensure we talk HAPROXY protocol to the backends
       proxy_protocol on;
     }

core/nginx/conf/proxy.conf

@@ -1,6 +1,7 @@
 # Default proxy setup
 proxy_set_header Host $http_host;
 proxy_set_header X-Real-IP $remote_addr;
+proxy_set_header X-Real-Port $remote_port;
 proxy_hide_header True-Client-IP;
 proxy_hide_header CF-Connecting-IP;
 

towncrier/newsfragments/2803.bugfix

@@ -0,0 +1 @@
+Improve auth-related logging