A propos des logs unifiés de macOS sierra et high sierra

On avait pour habitude de suivre les logs du service de messagerie avec la commande :

tail -f /var/log/mail.log

Et de mettre les logs en mode debug avec server admin

Depuis macOS 10.12, il faut envisager une méthode quelque peu différente :

Pour passer en mode debug, on utilisera la commande :

sudo log config --mode "level=debug" --subsystem com.apple.mail

Pour suivre les mails en live, on utilisera la commande :

log stream --level=debug --style syslog --predicate 'process == "pipe" or process == "postscreen" or process == "smtpd" or process == "qmgr" or process == "cleanup" and eventType == logEvent'

Filtering the log data using "process == "smtpd" OR process == "qmgr" OR (process == "cleanup" AND eventType == 1024)"
Timestamp (process)[PID]
2018-01-23 11:23:13.610223+0100 localhost smtpd[71468]: connect from localhost[::1]
2018-01-23 11:23:13.610669+0100 localhost smtpd[71468]: (smtpd) Created Activity ID: 0x80000000000799f5, Description: accessing SCDynamicStore
2018-01-23 11:23:13.629616+0100 localhost smtpd[71468]: 99AFA40F5F2: client=localhost[::1], sasl_method=DIGEST-MD5, sasl_username=martine.godard
2018-01-23 11:23:13.630366+0100 localhost cleanup[75440]: 99AFA40F5F2: message-id=
2018-01-23 11:23:13.653378+0100 localhost qmgr[366]: 99AFA40F5F2: from=, size=1754, nrcpt=1 (queue active)
2018-01-23 11:23:13.685305+0100 localhost smtpd[71468]: disconnect from localhost[::1] ehlo=1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=6
2018-01-23 11:23:14.074560+0100 localhost smtpd[71455]: 122CD40F60D: client=localhost[127.0.0.1]
2018-01-23 11:23:14.075451+0100 localhost cleanup[75651]: 122CD40F60D: message-id=
2018-01-23 11:23:14.075775+0100 localhost smtpd[71455]: disconnect from localhost[127.0.0.1] ehlo=1 mail=2 rcpt=2 data=2 noop=1 quit=1 commands=9
2018-01-23 11:23:14.075853+0100 localhost qmgr[366]: 122CD40F60D: from=, size=2445, nrcpt=1 (queue active)
2018-01-23 11:23:14.083911+0100 localhost qmgr[366]: 99AFA40F5F2: removed
2018-01-23 11:23:14.126021+0100 localhost qmgr[366]: 122CD40F60D: removed
2018-01-23 11:23:16.766945+0100 localhost smtpd[71350]: disconnect from unknown[192.168.1.53] ehlo=1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=6

De la même façon, pour obtenir la trace d’un mail particulier, par exemple par son numéro de mail queue, on pourra utiliser la commande suivante (équivalent de cat /var/log/mail.log |grep D43B041419C) :

log show --style syslog --predicate 'eventMessage contains[c] "D43B041419C" and eventType == logEvent' --last 3m

Je conseille vivement de mettre une limite dans le temps ou des bornes de date et heure pour limiter la durée de la recherche.
Dans mon exemple, les trois dernières minutes : –last 3m

Skipping info and debug messages, pass --info and/or --debug to include.
Filtering the log data using "eventMessage CONTAINS[c] "D43B041419C" AND eventType == 1024"
Timestamp (process)[PID]
2018-01-23 11:54:01.902551+0100 localhost smtpd[83871]: D43B041419C: client=localhost[127.0.0.1]
2018-01-23 11:54:01.903970+0100 localhost cleanup[83847]: D43B041419C: message-id=<1d1d7e7eb35b4f4b9b5f74cbbe0eb4fc>
2018-01-23 11:54:01.904516+0100 localhost qmgr[366]: D43B041419C: from=, size=33152, nrcpt=2 (queue active)
2018-01-23 11:54:01.914744+0100 localhost smtp[83320]: D2D9D41417A: to=, relay=127.0.0.1[127.0.0.1]:10024, delay=1, delays=0.14/0/0/0.89, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as D43B041419C)
2018-01-23 11:54:01.914805+0100 localhost smtp[83320]: D2D9D41417A: to=pierre@dscl.fr>, relay=127.0.0.1[127.0.0.1]:10024, delay=1, delays=0.14/0/0/0.89, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as D43B041419C)
2018-01-23 11:54:01.959081+0100 localhost pipe[77767]: D43B041419C: to=, orig_to=, relay=dovecot, delay=0.06, delays=0/0/0/0.05, dsn=2.0.0, status=sent (delivered via dovecot service)
2018-01-23 11:54:02.377018+0100 localhost pipe[77772]: D43B041419C: to=, orig_to=, relay=dovecot, delay=0.47, delays=0/0/0/0.47, dsn=2.0.0, status=sent (delivered via dovecot service)
2018-01-23 11:54:02.377399+0100 localhost qmgr[366]: D43B041419C: removed

En attendant que splunk sache lire les logs unifiés, on peut utiliser un script shell pour mettre à jour le fichier de log SMTP /var/log/mail-smtp.log :

# récupère les secondes de la dernière date du fichier de log et ajoute 1
sec=$(expr `tail -1 /var/log/mail-smtp.log |cut -c 18-19` + 1)

# récupère la date sans les secondes
shortdate=`tail -1 /var/log/mail-smtp.log |cut -c 1-17`

# génère la date de début du filtre en fonction de la date du dernier log
startdate=$shortdate$sec
enddate=`date "+%Y-%m-%d %H:%M:00"`

# écrit dans les logs que ce script a bien été exécuté et y met les bornes de dates
logger -is -t olivier "Add mail logs from $startdate to $enddate »

# lit les logs entre les dates de bornes dans la base de données et les injecte dans le fichier
# le grep est utilisé pour supprimer la ligne d’entête de la commande log show
# Timestamp (process)[PID]
# 2018-01-23 16:28:37.944885+0100 localhost qmgr[366]: 10EFF43E8DE: removed

log show --style syslog --predicate 'process == "smtpd" or process == "qmgr" or process == "cleanup" and eventType == logEvent' --start "$startdate" --end "$enddate" |grep -v Timestamp >> /var/log/mail-smtp.log

Publié dans Non classé et étiqueté , , , .