Debugging SASL LOGIN Authentication Failures: Decoding Usernames in Postfix/Dovecot Error Logs


28 views

When troubleshooting SMTP authentication issues in Postfix/Dovecot environments, we often encounter cryptic log entries like:

Dec 11 20:15:37 HOST postfix/smtpd[642]: warning: HOST[x.x.x.x]: SASL LOGIN authentication failed: UGFzc3dvcmQ6

The base64-encoded string UGFzc3dvcmQ6 decodes to "Password:", which tells us the authentication failed at the password stage but reveals nothing about the username being attempted.

To capture the complete authentication attempt, we need to configure more detailed logging:

# In /etc/dovecot/conf.d/10-logging.conf
auth_verbose = yes
auth_verbose_passwords = plain

This will log the full authentication exchange, including both username and password attempts (in plaintext - use with caution in production).

With verbose logging enabled, you'll see entries like:

auth: Debug: auth client connected (pid=1234)
auth: Debug: client in: AUTH    1   PLAIN   service=smtp    secured=no    lip=x.x.x.x    rip=y.y.y.y
auth: Debug: client in: CONT    1   AHRlc3R1c2VyAHRlc3RwYXNz
auth: Debug: client out: FAIL    1   reason=Password mismatch

The base64 string AHRlc3R1c2VyAHRlc3RwYXNz contains both username and password separated by a null byte. Decoding it:

echo "AHRlc3R1c2VyAHRlc3RwYXNz" | base64 -d
# Output: testuser\0testpass

For regular monitoring, create a script to parse logs:

#!/bin/bash
# parse_sasl_failures.sh
LOGFILE=/var/log/mail.log

grep "SASL LOGIN authentication failed" "$LOGFILE" | while read line; do
    timestamp=$(echo "$line" | awk '{print $1" "$2" "$3}')
    ip=$(echo "$line" | grep -oE '$$[0-9]+\.[0-9]+\.[0-9]+\.[0-9]+$$')
    pid=$(echo "$line" | grep -oE '$$[0-9]+$$' | head -1)
    
    # Find the corresponding verbose log entry
    verbose_line=$(grep -A2 "client in: CONT.*$pid" /var/log/mail.log | head -2 | tail -1)
    if [[ "$verbose_line" == *"CONT"* ]]; then
        b64_data=$(echo "$verbose_line" | awk '{print $4}')
        decoded=$(echo "$b64_data" | base64 -d)
        username=$(echo "$decoded" | cut -d$'\0' -f1)
        echo "$timestamp | PID $pid | IP $ip | Failed attempt for user: $username"
    fi
done

Remember that logging authentication attempts in plaintext has security implications:

  • Configure log file permissions (600) and ownership (root:root)
  • Consider using syslog-ng or rsyslog to redirect sensitive logs to a secured location
  • Disable verbose logging after troubleshooting

If you can't modify Dovecot configuration:

  1. Check all cron jobs that might be running mail scripts:
    grep -r "/usr/sbin/sendmail" /etc/cron*
  2. Examine PHP mail scripts:
    find /var/www -type f -name "*.php" -exec grep -l "mail(" {} \;
  3. Inspect systemd services that might be running mail clients

When troubleshooting Postfix/Dovecot mail servers, you'll often encounter SASL authentication failures like:

Dec 11 20:15:37 HOST postfix/smtpd[642]: warning: HOST[x.x.x.x]: SASL LOGIN authentication failed: UGFzc3dvcmQ6

This base64-encoded string "UGFzc3dvcmQ6" decodes to "Password:", indicating we're seeing the password prompt portion of the authentication exchange.

To identify the problematic username, we need to enable verbose SASL logging in Dovecot:

# /etc/dovecot/conf.d/10-logging.conf
auth_verbose = yes
auth_verbose_passwords = sha1
auth_debug = yes
auth_debug_passwords = yes

This will log the complete authentication sequence including usernames.

A complete failed authentication attempt will now show:

auth: Debug: auth client connected (pid=642)
auth: Debug: client in: AUTH    1       PLAIN   service=smtp    secured=no
auth: Debug: client in: AUTH    1       LOGIN   service=smtp    secured=no
auth: Debug: client out: CONT    1       VXNlcm5hbWU6
auth: Debug: client in: CONT    1       dXNlcm5hbWU=
auth: Debug: client out: CONT    1       UGFzc3dvcmQ6
auth: Debug: client in: CONT    1       d3JvbmdfcGFzc3dvcmQ=

Here we can see:
- "VXNlcm5hbWU6" decodes to "Username:"
- "dXNlcm5hbWU=" decodes to the actual username used
- "d3JvbmdfcGFzc3dvcmQ=" contains the invalid password

For production systems, implement this Python script to monitor auth attempts:

import base64
import re
from pathlib import Path

def decode_sasl(line):
    matches = re.findall(r'CONT\s+\d+\s+(\S+)', line)
    if matches and len(matches) >= 2:
        try:
            username = base64.b64decode(matches[1]).decode('utf-8')
            return username
        except:
            return None
    return None

def monitor_auth_log():
    log_file = Path('/var/log/mail.log')
    with open(log_file, 'r') as f:
        while True:
            line = f.readline()
            if 'SASL LOGIN authentication failed' in line:
                # Get subsequent lines for full auth exchange
                next_lines = [f.readline() for _ in range(6)]
                for auth_line in next_lines:
                    username = decode_sasl(auth_line)
                    if username:
                        print(f"Failed login attempt for: {username}")
                        break

if __name__ == '__main__':
    monitor_auth_log()

For immediate debugging without config changes:

# Check current auth processes
sudo doveadm auth debug username@domain.com

# Temporary verbose logging
sudo doveadm log reopen
sudo doveadm -D log find

This will show real-time authentication attempts including usernames.