Summary: check your main.cf for sleep commands.
Will Yardley:
> 10:31:53.449846 read(9, "RCPT TO:<recipi...@example.com>\r\n", 4096) = 31
> <0.000013>
> 10:31:53.450427 poll([{fd=13, events=POLLIN}], 1, 0) = 0 (Timeout) <0.000009>
> 10:31:53.450462 poll([{fd=13, events=POLLOUT}], 1, 3600000) = 1 ([{fd=13,
> revents=POLLOUT}]) <0.000009>
> 10:31:53.450493 write(13,
> "request\0rewrite\0rule\0local\0address\0recipi...@example.com\0\0", 56) = 56
> <0.000013>
> 10:31:53.450550 poll([{fd=13, events=POLLIN}], 1, 3600000) = 1 ([{fd=13,
> revents=POLLIN}]) <0.000010>
> 10:31:53.450603 read(13, "flags\0000\0address\0recipi...@example.com\0\0",
> 4096) = 37 <0.000012>
> 10:31:53.450651 poll([{fd=13, events=POLLIN}], 1, 0) = 0 (Timeout) <0.000009>
> 10:31:53.450689 poll([{fd=13, events=POLLOUT}], 1, 3600000) = 1 ([{fd=13,
> revents=POLLOUT}]) <0.000011>
> 10:31:53.450736 write(13,
> "request\0resolve\0sender\0\0address\0recipi...@example.com\0\0", 53) = 53
> <0.000078>
> 10:31:53.450858 poll([{fd=13, events=POLLIN}], 1, 3600000) = 1 ([{fd=13,
> revents=POLLIN}]) <0.002264>
> 10:31:53.453159 read(13,
> "flags\0000\0transport\0local\0nexthop\0hostname.example.com\0recipient\0recipi...@example.com\0flags\000256\0\0",
> 4096) = 92 <0.000025>
At this point the recipient address is extracted from the RCPT TO command,
and is has been syntax checked by smtpd_check_addr().
The recipient domain matches the local address class.
> 10:31:53.453244 flock(21, LOCK_SH) = 0 <0.000010>
> 10:31:53.453288 flock(21, LOCK_UN) = 0 <0.000010>
> 10:31:53.453319 flock(21, LOCK_SH) = 0 <0.000009>
> 10:31:53.453352 flock(21, LOCK_UN) = 0 <0.000009>
> 10:31:53.453381 flock(21, LOCK_SH) = 0 <0.000009>
> 10:31:53.453413 flock(21, LOCK_UN) = 0 <0.000022>
> 10:31:53.453455 flock(21, LOCK_SH) = 0 <0.000008>
> 10:31:53.453485 flock(21, LOCK_UN) = 0 <0.000008>
> 10:31:53.453525 flock(21, LOCK_SH) = 0 <0.000008>
> 10:31:53.453554 flock(21, LOCK_UN) = 0 <0.000008>
> 10:31:53.453580 flock(21, LOCK_SH) = 0 <0.000009>
> 10:31:53.453609 flock(21, LOCK_UN) = 0 <0.000008>
> 10:31:53.453635 flock(21, LOCK_SH) = 0 <0.000008>
> 10:31:53.453664 flock(21, LOCK_UN) = 0 <0.000008>
Somewhere early in the trace you will see what map is opened
with file descriptor 21.
The above is a bunch of table lookups in check_rcpt_maps()
to find out if the recipient is "known".
if (MATCH(rcpt_canon_maps, CONST_STR(reply->recipient))
|| MATCH(canonical_maps, CONST_STR(reply->recipient))
|| MATCH(virt_alias_maps, CONST_STR(reply->recipient)))
return (0);
I guess that we see lookups on one canonical or virtual map, with
search strings like user@domain, user, @domain; more lookups
if the address lookup succeeds and is followed by recursive queries
with the lookup result.
What happens next depends on whether the recipient matched
recipient_canonical_maps, canonical_maps, or virtual_alias maps.
If there was no match, then next we have lookups in local_recipient_maps
(the recipient domain matches the local address class).
Otherwise, next we have the evaluation of smtpd_mumble_restrictions.
> 10:31:53.453735 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000009>
> 10:31:53.453774 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
> <0.000011>
> 10:31:53.453813 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000008>
> 10:31:53.453841 nanosleep({1, 0}, 0x7fffa29253c0) = 0 <1.000073>
When I execute the sleep(1) call on Linux in a test program,
I see this:
rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
nanosleep({1, 0}, 0x7fffffffe2b0) = 0
So we can safely bet that a sleep(1) call is happening here.
If there was no match with canonical/virtual maps, then this is
happening in one of your local_recipient_maps drivers.
Otherwise this happens with evaluation of smtpd_mumble_restrictions.
Do you have a sleep in main.cf?
> 10:31:54.453978 flock(23, LOCK_SH) = 0 <0.000011>
> 10:31:54.454030 flock(23, LOCK_UN) = 0 <0.000010>
> 10:31:54.454062 flock(23, LOCK_SH) = 0 <0.000009>
> 10:31:54.454096 flock(23, LOCK_UN) = 0 <0.000009>
> 10:31:54.454139 flock(23, LOCK_SH) = 0 <0.000008>
> 10:31:54.454171 flock(23, LOCK_UN) = 0 <0.000021>
> 10:31:54.454213 flock(23, LOCK_SH) = 0 <0.000009>
> 10:31:54.454260 flock(23, LOCK_UN) = 0 <0.000009>
Somewhere early in the trace you will see what map is opened
with file descriptor 23.
If canonical/virtual lookups failed, then this is local aliases
lookup, then we have either one (bare username) or two (user+foo,
user), and more if the lookup succeeds and becomes the query for
recursive lookup. That would explain the 4 lookups.
Otherwise, this is Postfix access map lookup.
Wietse
