Postfix pipe delayed

Question

I am running postfix on a raspberry pi. My outdoor camera is sending an email when it detects any motion. I am piping this email to a script. There is always a delay of 2-3s but the pi is 99% idle. So I assume it is a config issue.

Log:

Oct  3 18:07:55 raspberrypi postfix/smtpd[11348]: connect from OutdoorCam.fritz.box[192.168.173.39]
Oct  3 18:07:55 raspberrypi postfix/smtpd[11348]: NOQUEUE: filter: RCPT from OutdoorCam.fritz.box[192.168.173.39]: <fhem@raspberrypi.local>: Sender address triggers FILTER triggerCamAlert:dummy; from=<fhem@raspberrypi.local> to=<fhem@raspberrypi.local> proto=ESMTP helo=<localhost>
Oct  3 18:07:55 raspberrypi postfix/smtpd[11348]: 38F713FED0: client=OutdoorCam.fritz.box[192.168.173.39]
Oct  3 18:07:55 raspberrypi postfix/cleanup[11351]: 38F713FED0: message-id=<>
Oct  3 18:07:55 raspberrypi postfix/qmgr[24540]: 38F713FED0: from=<fhem@raspberrypi.local>, size=469, nrcpt=1 (queue active)
Oct  3 18:07:55 raspberrypi postfix/smtpd[11348]: disconnect from OutdoorCam.fritz.box[192.168.173.39]
Oct  3 18:07:57 raspberrypi postfix/pipe[11352]: 38F713FED0: to=<fhem@raspberrypi>, orig_to=<fhem@raspberrypi.local>, relay=triggerCamAlert, delay=2.5, delays=0.07/0/0/2.4, dsn=2.0.0, status=sent (delivered via triggerCamAlert service)
Oct  3 18:07:57 raspberrypi postfix/qmgr[24540]: 38F713FED0: removed

master.cf

# ==========================================================================
# service type  private unpriv  chroot  wakeup  maxproc command + args
#               (yes)   (yes)   (yes)   (never) (100)
# ==========================================================================
smtp      inet  n       -       -       -       -       smtpd
#smtp      inet  n       -       -       -       1       postscreen
#smtpd     pass  -       -       -       -       -       smtpd
#dnsblog   unix  -       -       -       -       0       dnsblog
#tlsproxy  unix  -       -       -       -       0       tlsproxy
#submission inet n       -       -       -       -       smtpd
#  -o syslog_name=postfix/submission
#  -o smtpd_tls_security_level=encrypt
#  -o smtpd_sasl_auth_enable=yes
#  -o smtpd_client_restrictions=permit_sasl_authenticated,reject
#  -o milter_macro_daemon_name=ORIGINATING
#smtps     inet  n       -       -       -       -       smtpd
#  -o syslog_name=postfix/smtps
#  -o smtpd_tls_wrappermode=yes
#  -o smtpd_sasl_auth_enable=yes
#  -o smtpd_client_restrictions=permit_sasl_authenticated,reject
#  -o milter_macro_daemon_name=ORIGINATING
#628       inet  n       -       -       -       -       qmqpd
pickup    fifo  n       -       -       60      1       pickup
cleanup   unix  n       -       -       -       0       cleanup
qmgr      fifo  n       -       n       300     1       qmgr
#qmgr     fifo  n       -       n       300     1       oqmgr
tlsmgr    unix  -       -       -       1000?   1       tlsmgr
rewrite   unix  -       -       -       -       -       trivial-rewrite
bounce    unix  -       -       -       -       0       bounce
defer     unix  -       -       -       -       0       bounce
trace     unix  -       -       -       -       0       bounce
verify    unix  -       -       -       -       1       verify
flush     unix  n       -       -       1000?   0       flush
proxymap  unix  -       -       n       -       -       proxymap
proxywrite unix -       -       n       -       1       proxymap
smtp      unix  -       -       -       -       -       smtp
relay     unix  -       -       -       -       -       smtp
#       -o smtp_helo_timeout=5 -o smtp_connect_timeout=5
showq     unix  n       -       -       -       -       showq
error     unix  -       -       -       -       -       error
retry     unix  -       -       -       -       -       error
discard   unix  -       -       -       -       -       discard
local     unix  -       n       n       -       -       local
virtual   unix  -       n       n       -       -       virtual
lmtp      unix  -       -       -       -       -       lmtp
anvil     unix  -       -       -       -       1       anvil
scache    unix  -       -       -       -       1       scache
#
# ====================================================================
# Interfaces to non-Postfix software. Be sure to examine the manual
# pages of the non-Postfix software to find out what options it wants.
#
# Many of the following services use the Postfix pipe(8) delivery
# agent.  See the pipe(8) man page for information about ${recipient}
# and other message envelope options.
# ====================================================================
#
# maildrop. See the Postfix MAILDROP_README file for details.
# Also specify in main.cf: maildrop_destination_recipient_limit=1
#
maildrop  unix  -       n       n       -       -       pipe
  flags=DRhu user=vmail argv=/usr/bin/maildrop -d ${recipient}

triggerCamAlert unix - n n - - pipe flags=X user=filter argv=/opt/fhem/triggerCamAlert.sh

Any idea what could cause this delay?

Any hint is very welcome!

Tobelix

score 3 · Answer 1 · answered Oct 03 '18 at 20:37

For the discerning reader the information is already in your log file.

You guesstimate of "a delay of 2-3s" is in your example is actually spot on with exactly 2.5 seconds:

Oct  3 18:07:57 raspberrypi postfix/pipe[11352]: ... delay=2.5, delays=0.07/0/0/2.4 ...
                                                     ^^^^^^^^^  ^^^^^^^^^^^^^^^^^^^

The delays=a/b/c/d is actually a breakdown to which part of the SMTP transaction takes how much time as explained in this Q&A.

The longest at 2.4 seconds is the message transmission time.

It simply takes a the sender a long time to submit the complete message, there is nothing inherently wrong with your Postfix config that is to blame.

Thanks for your reply! But everything is happening on localhost. The message size is very small. I can hardly believe that it really takes 2.4s for the message transmission. If so, is there any part in the config where I could try to reduce that time? — Tobelix, Oct 07 '18 at 09:21

Postfix pipe delayed

1 Answers1