ไล่ Dovecot IMAP/POP fail บน DirectAdmin แล้วเก็บ log ยาว 90 วัน

ใน Part 1 ผมเล่าเรื่องไล่ exim mainlog เพื่อตามหาเครื่องที่ตั้งรหัสผิดค้างอยู่ใน LAN จนทำให้ทั้ง subnet โดน LFD แบน พอบทความลงไปแล้วก็มีคำถามตามมาหลายข้อ ส่วนใหญ่วนอยู่สามเรื่อง — ฝั่ง IMAP/POP ที่เป็นการ "ดึงเมล" เข้ามาดูที่ log ไหน, ทำไม log ของ DirectAdmin มันหายเร็วจนย้อนดูไม่ทัน, แล้วถ้าอยากเก็บยาว 90 วันต้องไปแก้ตรงไหน

ผมเลยมาต่อให้ครบในภาคนี้ เน้นเฉพาะ stack ที่ DirectAdmin ใช้จริง คือ exim ฝั่ง SMTP, dovecot ฝั่ง IMAP/POP, และ LFD/CSF ฝั่งกันบุกรุก ใครที่เครื่องใช้ postfix แทนของ DA path มันจะต่างไป (ไปอยู่ที่ /var/log/maillog แทน) แต่ pattern โดยรวมคล้ายกัน apply ตามเองได้ไม่ยาก ตอนท้ายผมเขียนวิธีปรับไว้ให้ด้วย

Placeholder ที่ใช้ในบทความนี้

ผมใช้ placeholder ชุดเดิมต่อจาก Part 1 เพื่อกันข้อมูลจริงหลุด เวลาเอาไปใช้ก็แทนด้วยค่าของเครื่องตัวเองได้เลย

• example.com คือโดเมนลูกค้าตัวอย่าง
• 203.0.113.x กับ <server-ip> คือ public IP (ฝั่ง remote และฝั่ง server)
• 192.168.1.x คือ LAN IP ภายใน (RFC1918)
• [email protected] คือ mail account ตัวอย่าง

Mail log paths บน DirectAdmin

จุดที่คนพลาดบ่อยที่สุดคือไปหา log ผิดที่ ตาม tutorial ทั่วไปมักบอกให้ดู /var/log/exim4/mainlog หรือ /var/log/maillog แต่บน DirectAdmin (ผมตรวจบน DA-Debian จริง) มัน layout คนละแบบ ของจริงเป็นแบบนี้

ขยายความแต่ละไฟล์

• /var/log/exim/mainlog — exim ฝั่ง SMTP (ตัวที่ผม cover ไปแล้วใน Part 1)
• /var/log/exim/rejectlog — connection ที่โดน reject ตั้งแต่ก่อนถึง data phase
• /var/log/mail.log — dovecot IMAP/POP ที่วิ่งผ่าน rsyslog มาลง ตัวนี้แหละคือพระเอกของภาคนี้
• /var/log/dovecot-lmtp.log — LMTP delivery ตอน exim ส่งเมลเข้า mailbox ของ dovecot
• /var/log/lfd.log — event ของ CSF/LFD

permission ของไฟล์พวกนี้ปกติเป็น root:root หรือ root:adm คืออ่านได้แค่ root เท่านั้น

เริ่มจากตรวจก่อนว่า log ที่เราจะใช้มีอยู่ครบไหม

ls -la /var/log/exim/mainlog \
       /var/log/mail.log \
       /var/log/dovecot-lmtp.log \
       /var/log/lfd.log

Dovecot IMAP / POP fail pattern

เครื่องที่ตั้งรหัสผิดค้างไว้ในออฟฟิศ ปกติมันจะ fail ทั้งสองฝั่ง — ทั้ง SMTP ตอนส่งเมล (เรื่องของ Part 1) และทั้ง IMAP/POP ตอนดึงเมลเข้ามา (เรื่องของภาคนี้) เพราะ mail client มันใช้รหัสเดียวกันทั้งส่งและรับ ดูพร้อมกันสองฝั่งจะเห็นภาพชัดขึ้นเยอะ

จุดที่หลายคนยังไม่รู้คือ POP3 fail มักจะเยอะกว่า SMTP fail หลายเท่า เหตุผลง่ายมาก — mail client มัน poll inbox ทุก 1 ถึง 5 นาทีอยู่แล้ว ทุกครั้งที่ poll ด้วยรหัสผิดก็นับเป็น fail หนึ่งครั้ง ส่วน SMTP fail จะเกิดเฉพาะตอนผู้ใช้กดส่งเมลเท่านั้น ความถี่จึงต่างกันมาก ตรงนี้จะกลายเป็นเบาะแสสำคัญในข้อถัดไป

หน้าตา log ตอน login สำเร็จ (IMAP)

May 25 10:05:38 mail dovecot: imap-login: Login: user=<[email protected]>, method=PLAIN, rip=203.0.113.x, lip=<server-ip>, mpid=12345, TLS, session=<aBcDefGhIj>

หน้าตา log ตอน login ล้มเหลว (IMAP)

May 25 08:07:19 mail dovecot: imap-login: Disconnected (auth failed, 1 attempts in 5 secs): user=<[email protected]>, method=PLAIN, rip=203.0.113.x, lip=<server-ip>, TLS, session=<aBcDefGhIj>

ฝั่ง POP3 ใช้ pattern เดียวกันเป๊ะ เปลี่ยนแค่ imap-login เป็น pop3-login เท่านั้น

หา account ที่ IMAP fail เยอะที่สุดของวันนี้

TODAY=$(date "+%b %e" | sed 's/  / /')          # syslog format "May 25" (ระวัง double-space ถ้าวันที่ < 10)
LOG=/var/log/mail.log

grep "^$TODAY " $LOG \
  | grep 'imap-login: Disconnected (auth failed' \
  | grep -oE 'user=<[^>]+>' | sort | uniq -c | sort -rn | head

หา IP ที่ IMAP fail เยอะที่สุดของวันนี้

grep "^$TODAY " $LOG \
  | grep 'imap-login: Disconnected (auth failed' \
  | grep -oE 'rip=[0-9.]+' | sed 's/rip=//' | sort | uniq -c | sort -rn | head

นับรวม IMAP กับ POP3 fail ของ account เดียวในวันนี้

[email protected]
grep "^$TODAY " /var/log/mail.log \
  | grep -E '(imap-login|pop3-login): Disconnected \(auth failed' \
  | grep -c "user=<$ACCT>"

Cross-protocol check — แยก stuck client ออกจาก attacker

ข้อนี้ผมใช้บ่อยที่สุดในงานจริง เพราะมันคือตัวตัดสินว่าเคสที่เจอเป็น "เครื่องในออฟฟิศตั้งรหัสผิดค้าง" หรือเป็น "บอทจากข้างนอกพยายามเดารหัส" ซึ่งสองอย่างนี้วิธีจัดการคนละทางกันเลย

หลักการคือเทียบจำนวน fail ข้าม protocol ของ account เดียวกัน

[email protected]

echo "-- SMTP (exim) fail --"
grep "set_id=$ACCT" /var/log/exim/mainlog | grep -c 'authenticator failed'

echo "-- IMAP fail --"
grep "user=<$ACCT>" /var/log/mail.log | grep -c 'imap-login: Disconnected (auth failed'

echo "-- POP3 fail --"
grep "user=<$ACCT>" /var/log/mail.log | grep -c 'pop3-login: Disconnected (auth failed'

วิธีอ่านผลที่ผมยึดมาตลอด

จุดสังเกตคือ stuck client มันจะ poll inbox อัตโนมัติทุกไม่กี่นาที ทำให้ POP3/IMAP fail พุ่งเร็วมาก แต่ SMTP fail แทบไม่ขยับเพราะคนไม่ได้กดส่งเมลบ่อย ส่วน attacker ที่ยิงเดารหัสมันจะลองทุก protocol พอๆ กัน ตัวเลขเลยใกล้เคียง

เก็บ log 90 วัน — แก้ logrotate ของ DirectAdmin

นี่คือต้นเหตุที่หลายคนเจอว่า "อยากย้อนดู แต่ log หายไปแล้ว" — default ของ DirectAdmin มันเก็บสั้นมาก ผมไปเปิดดู config ทุกตัวแล้ว ฝั่ง exim กับ dovecot ตั้ง weekly + rotate 4 เท่ากับเก็บได้ราว 28 วัน ส่วน LFD แย่กว่านั้นคือ rotate 1 หรือเก็บได้แค่ 7 วันเท่านั้น

ปัญหาคือเวลาตามเคสจริง ผมเคยต้องย้อนดูถึง 60 ถึง 80 วันกว่าจะเจอจุดที่ password เริ่มผิด เพราะลูกค้าบางคนกว่าจะรู้ตัวว่าใช้ไม่ได้ก็ผ่านไปเป็นเดือน เพราะงั้นในทางปฏิบัติ ผมตั้งเป้าไว้ว่าอย่างน้อย 90 วันถึงจะพอใช้งานจริง

เช็คก่อนว่า config ปัจจุบันเป็นยังไง

cat /etc/logrotate.d/exim
cat /etc/logrotate.d/dovecot
cat /etc/logrotate.d/lfd
cat /etc/logrotate.d/rsyslog               # มี /var/log/mail.log อยู่ในนี้
cat /etc/logrotate.conf | grep -E 'rotate|weekly|daily|compress'

Default ของ exim ที่ผมเจอบน DA-Debian หน้าตาประมาณนี้

/var/log/exim/mainlog /var/log/exim/processlog /var/log/exim/rejectlog /var/log/exim/paniclog {
    missingok
    sharedscripts
}

จะเห็นว่าไม่มี rotate N, ไม่มี compress, ไม่มี daily เลย แปลว่ามันไปใช้ค่า default จาก /etc/logrotate.conf ซึ่งคือ weekly + rotate 4 เท่ากับ 28 วัน และไม่บีบอัด

override ฝั่ง exim เป็น 90 วัน + compress

แก้ /etc/logrotate.d/exim

/var/log/exim/mainlog /var/log/exim/processlog /var/log/exim/rejectlog /var/log/exim/paniclog {
    daily
    rotate 90
    compress
    delaycompress
    missingok
    notifempty
    sharedscripts
}

override ฝั่ง dovecot

แก้ /etc/logrotate.d/dovecot

/var/log/dovecot*.log {
    daily
    rotate 90
    compress
    delaycompress
    missingok
    notifempty
    sharedscripts
    postrotate
        kill -s 0 `cat /var/run/dovecot/master.pid` || kill -s USR1 `cat /var/run/dovecot/master.pid`
    endscript
}

override ฝั่ง mail.log (อยู่ใน rsyslog)

ตัว /var/log/mail.log ที่เป็น log ของ dovecot IMAP/POP ปกติจะถูกจัดการอยู่ใน /etc/logrotate.d/rsyslog

/var/log/mail.log
{
    daily
    rotate 90
    missingok
    notifempty
    compress
    delaycompress
    postrotate
        /usr/lib/rsyslog/rsyslog-rotate
    endscript
}

override ฝั่ง LFD — ตัวที่ default แค่ 7 วัน

ตัวนี้สำคัญมาก เพราะ default ของ DA เก็บแค่ 7 วัน ซึ่งสั้นเกินจะตามเคสไหนทัน แก้ /etc/logrotate.d/lfd

/var/log/lfd.log {
    daily
    rotate 90
    compress
    delaycompress
    missingok
    notifempty
}
/var/log/lfd_messenger.log {
    daily
    rotate 90
    compress
    delaycompress
    missingok
    notifempty
}

dry-run ก่อน apply จริง

อย่าพึ่ง force rotate เด็ดขาด ให้ทดสอบด้วย dry-run ก่อนเสมอ

logrotate -d /etc/logrotate.d/exim           # dry-run ดู debug output ว่าจะทำอะไรบ้าง
logrotate -d /etc/logrotate.d/dovecot
logrotate -d /etc/logrotate.d/lfd
logrotate -d /etc/logrotate.d/rsyslog

ถ้า dry-run ไม่ขึ้น error config มันจะถูก apply เองอัตโนมัติคืนนี้ตอน cron daily รัน (/etc/cron.daily/logrotate)

ดู disk impact ก่อนเพิ่ม retention

เพิ่ม retention เป็น 90 วันแปลว่ากิน disk มากขึ้น ต้องเช็คก่อนว่าพื้นที่พอ

ls -lh /var/log/exim/mainlog* /var/log/mail.log* /var/log/dovecot* /var/log/lfd* 2>/dev/null
du -sh /var/log
df -h /var

mail server ขนาดกลางของผม (ราว 50 domain, ราว 200 mailbox) ใช้พื้นที่ราว 3 ถึง 5 GB สำหรับ log 90 วันหลัง gzip แล้ว ถ้าเครื่องไหนแยก partition /var ออกมาต่างหากต้องเช็คให้ดี เพราะถ้า log เต็ม partition แล้ว rsyslog crash นี่ตามแก้ลำบาก

Query ย้อนหลังใน rotated logs ที่ถูก gzip

หลังจากเปิด compress ในข้อก่อนหน้า ไฟล์เก่าจะกลายเป็น .gz ทั้งหมด ตรงนี้ใช้ zgrep แทน grep ได้ตรงๆ มันอ่านทั้งไฟล์ปกติและไฟล์ gzip ได้ในคำสั่งเดียว

ดู IMAP fail ของ account ตลอด 90 วัน

[email protected]
zgrep -h "user=<$ACCT>" /var/log/mail.log* \
  | grep -c 'imap-login: Disconnected (auth failed'

ดู IP ที่ account นั้นเคย login สำเร็จย้อนหลัง 90 วัน

zgrep -h "user=<$ACCT>" /var/log/mail.log* \
  | grep 'imap-login: Login' \
  | grep -oE 'rip=[0-9.]+' | sed 's/rip=//' \
  | sort | uniq -c | sort -rn | head -20

เคสที่ผมเจอบ่อยมากคือลูกค้ายืนยันว่า "device ของผมเคยใช้ได้นี่" พอเปิด log ย้อน 60 วันดู มันก็ login สำเร็จมาตลอดจริงๆ แล้วจู่ๆ มาเริ่ม fail วันที่ X ตรงนี้แหละที่ confirm ได้ว่า password ถูกเปลี่ยน (บ่อยครั้งมีคนในออฟฟิศเข้า webmail ไปเปลี่ยนเอง) ไม่ใช่ device พัง

ฝั่ง SMTP (exim) ใช้ zgrep แบบเดียวกัน

zgrep -h "set_id=$ACCT" /var/log/exim/mainlog* | grep -c 'authenticator failed'

One-liners ภาคขยาย

ชุดนี้ต่อยอดจากที่ลงไว้ใน Part 1 เก็บไว้แปะไว้ใช้ตอนต้องไล่เคสด่วน

Top 10 account ที่ IMAP fail วันนี้

TODAY=$(date "+%b %e" | sed 's/  / /')
grep "^$TODAY " /var/log/mail.log \
  | grep 'imap-login: Disconnected (auth failed' \
  | grep -oE 'user=<[^>]+>' | sort | uniq -c | sort -rn | head

Top 10 IP ที่ IMAP fail วันนี้

grep "^$TODAY " /var/log/mail.log \
  | grep 'imap-login: Disconnected (auth failed' \
  | grep -oE 'rip=[0-9.]+' | sed 's/rip=//' | sort | uniq -c | sort -rn | head

หา account ที่เคย login สำเร็จใน 60 วัน แต่เงียบไปใน 7 วันล่าสุด (อาจเลิกใช้ หรือ device หาย)

# success ใน 60 วัน (mainlog + rotated)
zgrep -h 'A=[a-z_]*:' /var/log/exim/mainlog* \
  | grep -oE 'A=[a-z_]*:[^ ]+' | sort -u > /home/<user>/all60

# success ใน 7 วันล่าสุด
zgrep -h 'A=[a-z_]*:' /var/log/exim/mainlog{,.[1-7]}* 2>/dev/null \
  | grep -oE 'A=[a-z_]*:[^ ]+' | sort -u > /home/<user>/last7

comm -23 /home/<user>/all60 /home/<user>/last7

นับ fail ทุก protocol ของ 1 account ตลอด 90 วัน

[email protected]
echo "-- SMTP (exim) --"
zgrep -h "set_id=$ACCT" /var/log/exim/mainlog* | grep -c 'authenticator failed'
echo "-- IMAP+POP (dovecot) --"
zgrep -h "user=<$ACCT>" /var/log/mail.log* | grep -c 'Disconnected (auth failed'

สรุป workflow ภาคขยาย

ทั้งหมดร้อยเรียงเป็นเส้นทางเดียวกันได้ตามนี้

• IMAP/POP fail เยอะ ไปดู §2 dovecot pattern
• สงสัยว่าเป็น stuck client จริงไหม ไปเทียบ ratio ข้าม protocol ที่ §3
• ต้องย้อนเกิน 60 วัน ต้องตั้ง logrotate 90 ที่ §4 แล้วใช้ zgrep ที่ §5
• หา account ที่ inactive หรือเงียบไป ใช้ one-liner ตัวสุดท้ายใน §6

สำหรับคนที่ใช้ postfix แทน exim

ใครที่เครื่องใช้ postfix แทน exim ของ DA path มันจะต่างไป ฝั่ง CentOS จะอยู่ที่ /var/log/maillog ส่วน Debian บางตัวก็ผสมไปอยู่ที่ /var/log/mail.log format เป็น syslog เหมือนกันแต่ข้อความต่าง เช่นตอน auth fail จะขึ้นเป็น SASL PLAIN authentication failed ปรับ regex ในคำสั่งข้างบนนิดเดียวก็ใช้ได้

ส่วนตัวผมรันชุดนี้มาเกือบปีแล้ว เห็นว่ามันช่วยให้ตามเคสได้ไวขึ้นจริงเลยเอามาเขียนต่อให้ ใครมี trick ที่เด็ดกว่านี้ ไม่ว่าจะ regex สั้นกว่า, script ที่ auto-correlate exim กับ dovecot เข้าด้วยกัน หรือ dashboard สรุปผล มาแชร์กันได้

ตามสะดวกครับ ใครจะใช้ exim หรือ postfix, จะเก็บ 30 วันหรือ 90 วัน หลักการเหมือนกันหมด คือดูทั้งสองฝั่ง แล้วเก็บ log ให้ยาวพอที่จะย้อนกลับไปหาจุดเริ่มได้