consistent fork-time debug
[users/jgh/exim.git] / test / stderr / 0183
index b5e5deb46b32c60756595868465e00d3fd6c4995..0de70e79b0f3b597bf30fbdeb5f4c1830fa94b3c 100644 (file)
@@ -3,9 +3,7 @@ changed uid/gid: forcing real = effective
   uid=uuuu gid=CALLER_GID pid=pppp
 configuration file is TESTSUITE/test-config
 admin user
   uid=uuuu gid=CALLER_GID pid=pppp
 configuration file is TESTSUITE/test-config
 admin user
-DSN: srv propagating DSN
-DSN: useryz propagating DSN
-DSN: lookuphost propagating DSN
+dropping to exim gid; retaining priv uid
 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
 sender address = CALLER@myhost.test.ex
 Address testing: uid=uuuu gid=EXIM_GID euid=uuuu egid=EXIM_GID
 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
 sender address = CALLER@myhost.test.ex
 Address testing: uid=uuuu gid=EXIM_GID euid=uuuu egid=EXIM_GID
@@ -27,13 +25,20 @@ userx in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=userx domain=test.again.dns
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=userx domain=test.again.dns
+checking local_parts
+userx in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for userx@test.again.dns
   domain = test.again.dns
 calling lookuphost router
 lookuphost router called for userx@test.again.dns
   domain = test.again.dns
-Return from DNS lookup of test.again.dns (MX) faked for testing
+test.again.dns in "*"? yes (matched "*")
+DNS lookup of test.again.dns (MX) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of test.again.dns (MX) gave TRY_AGAIN
 test.again.dns in dns_again_means_nonexist? no (option unset)
 returning DNS_AGAIN
 DNS lookup of test.again.dns (MX) gave TRY_AGAIN
 test.again.dns in dns_again_means_nonexist? no (option unset)
 returning DNS_AGAIN
+ writing neg-cache entry for test.again.dns-MX-xxxx, ttl -1
 lookuphost router: defer for userx@test.again.dns
   message: host lookup did not complete
 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
 lookuphost router: defer for userx@test.again.dns
   message: host lookup did not complete
 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
@@ -54,9 +59,12 @@ abcd in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=test.again.dns
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=test.again.dns
+checking local_parts
+abcd in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for abcd@test.again.dns
   domain = test.again.dns
 calling lookuphost router
 lookuphost router called for abcd@test.again.dns
   domain = test.again.dns
+test.again.dns in "*"? yes (matched "*")
 DNS lookup of test.again.dns-MX: using cached value DNS_AGAIN
 lookuphost router: defer for abcd@test.again.dns
   message: host lookup did not complete
 DNS lookup of test.again.dns-MX: using cached value DNS_AGAIN
 lookuphost router: defer for abcd@test.again.dns
   message: host lookup did not complete
@@ -78,13 +86,25 @@ abcd in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=ten-1.test.ex
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=ten-1.test.ex
+checking local_parts
+abcd in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for abcd@ten-1.test.ex
   domain = ten-1.test.ex
 calling lookuphost router
 lookuphost router called for abcd@ten-1.test.ex
   domain = ten-1.test.ex
+ten-1.test.ex in "*"? yes (matched "*")
 DNS lookup of ten-1.test.ex (MX) using fakens
 DNS lookup of ten-1.test.ex (MX) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of ten-1.test.ex (MX) gave NO_DATA
 returning DNS_NODATA
 DNS lookup of ten-1.test.ex (MX) gave NO_DATA
 returning DNS_NODATA
+faking res_search(MX) response length as 65535
+ writing neg-cache entry for ten-1.test.ex-MX-xxxx, ttl 3000
+ten-1.test.ex (MX resp) DNSSEC
 DNS lookup of ten-1.test.ex (A) using fakens
 DNS lookup of ten-1.test.ex (A) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
@@ -117,15 +137,20 @@ useryz router called for usery@test.again.dns
   domain = test.again.dns
 route_item = * $domain bydns
 test.again.dns in "*"? yes (matched "*")
   domain = test.again.dns
 route_item = * $domain bydns
 test.again.dns in "*"? yes (matched "*")
-original list of hosts = "$domain" options = bydns
-expanded list of hosts = "test.again.dns" options = bydns
+original list of hosts = '$domain' options = 'bydns'
+expanded list of hosts = 'test.again.dns' options = 'bydns'
 set transport smtp
 finding IP address for test.again.dns
 doing DNS lookup
 set transport smtp
 finding IP address for test.again.dns
 doing DNS lookup
-Return from DNS lookup of test.again.dns (A) faked for testing
+test.again.dns in "*"? yes (matched "*")
+DNS lookup of test.again.dns (A) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of test.again.dns (A) gave TRY_AGAIN
 test.again.dns in dns_again_means_nonexist? no (option unset)
 returning DNS_AGAIN
 DNS lookup of test.again.dns (A) gave TRY_AGAIN
 test.again.dns in dns_again_means_nonexist? no (option unset)
 returning DNS_AGAIN
+ writing neg-cache entry for test.again.dns-A-xxxx, ttl -1
 useryz router: defer for usery@test.again.dns
   message: host lookup for test.again.dns did not complete (DNS timeout?)
 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
 useryz router: defer for usery@test.again.dns
   message: host lookup for test.again.dns did not complete (DNS timeout?)
 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
@@ -148,10 +173,11 @@ useryz router called for userz@test.again.dns
   domain = test.again.dns
 route_item = * $domain bydns
 test.again.dns in "*"? yes (matched "*")
   domain = test.again.dns
 route_item = * $domain bydns
 test.again.dns in "*"? yes (matched "*")
-original list of hosts = "$domain" options = bydns
-expanded list of hosts = "test.again.dns" options = bydns
+original list of hosts = '$domain' options = 'bydns'
+expanded list of hosts = 'test.again.dns' options = 'bydns'
 finding IP address for test.again.dns
 doing DNS lookup
 finding IP address for test.again.dns
 doing DNS lookup
+test.again.dns in "*"? yes (matched "*")
 DNS lookup of test.again.dns-A: using cached value DNS_AGAIN
 useryz router: defer for userz@test.again.dns
   message: host lookup for test.again.dns did not complete (DNS timeout?)
 DNS lookup of test.again.dns-A: using cached value DNS_AGAIN
 useryz router: defer for userz@test.again.dns
   message: host lookup for test.again.dns did not complete (DNS timeout?)
@@ -173,11 +199,17 @@ xyz in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=xyz domain=ten-1.test.ex
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=xyz domain=ten-1.test.ex
+checking local_parts
+xyz in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for xyz@ten-1.test.ex
   domain = ten-1.test.ex
 calling lookuphost router
 lookuphost router called for xyz@ten-1.test.ex
   domain = ten-1.test.ex
+ten-1.test.ex in "*"? yes (matched "*")
 DNS lookup of ten-1.test.ex-MX: using cached value DNS_NODATA
 DNS lookup of ten-1.test.ex (A) using fakens
 DNS lookup of ten-1.test.ex-MX: using cached value DNS_NODATA
 DNS lookup of ten-1.test.ex (A) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
@@ -190,15 +222,13 @@ routed by lookuphost router
   transport: smtp
   host ten-1.test.ex [V4NET.0.0.1]
 search_tidyup called
   transport: smtp
   host ten-1.test.ex [V4NET.0.0.1]
 search_tidyup called
->>>>>>>>>>>>>>>> Exim pid=pppp terminating with rc=1 >>>>>>>>>>>>>>>>
+>>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=1 >>>>>>>>>>>>>>>>
 Exim version x.yz ....
 changed uid/gid: forcing real = effective
   uid=uuuu gid=CALLER_GID pid=pppp
 configuration file is TESTSUITE/test-config
 admin user
 Exim version x.yz ....
 changed uid/gid: forcing real = effective
   uid=uuuu gid=CALLER_GID pid=pppp
 configuration file is TESTSUITE/test-config
 admin user
-DSN: srv propagating DSN
-DSN: useryz propagating DSN
-DSN: lookuphost propagating DSN
+dropping to exim gid; retaining priv uid
 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
 sender address = CALLER@myhost.test.ex
 Address testing: uid=uuuu gid=EXIM_GID euid=uuuu egid=EXIM_GID
 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
 sender address = CALLER@myhost.test.ex
 Address testing: uid=uuuu gid=EXIM_GID euid=uuuu egid=EXIM_GID
@@ -220,12 +250,19 @@ userx in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=userx domain=test.fail.dns
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=userx domain=test.fail.dns
+checking local_parts
+userx in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for userx@test.fail.dns
   domain = test.fail.dns
 calling lookuphost router
 lookuphost router called for userx@test.fail.dns
   domain = test.fail.dns
-Return from DNS lookup of test.fail.dns (MX) faked for testing
+test.fail.dns in "*"? yes (matched "*")
+DNS lookup of test.fail.dns (MX) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of test.fail.dns (MX) gave NO_RECOVERY
 returning DNS_FAIL
 DNS lookup of test.fail.dns (MX) gave NO_RECOVERY
 returning DNS_FAIL
+ writing neg-cache entry for test.fail.dns-MX-xxxx, ttl -1
 lookuphost router: defer for userx@test.fail.dns
   message: host lookup did not complete
 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
 lookuphost router: defer for userx@test.fail.dns
   message: host lookup did not complete
 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
@@ -246,9 +283,12 @@ abcd in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=test.fail.dns
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=test.fail.dns
+checking local_parts
+abcd in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for abcd@test.fail.dns
   domain = test.fail.dns
 calling lookuphost router
 lookuphost router called for abcd@test.fail.dns
   domain = test.fail.dns
+test.fail.dns in "*"? yes (matched "*")
 DNS lookup of test.fail.dns-MX: using cached value DNS_FAIL
 lookuphost router: defer for abcd@test.fail.dns
   message: host lookup did not complete
 DNS lookup of test.fail.dns-MX: using cached value DNS_FAIL
 lookuphost router: defer for abcd@test.fail.dns
   message: host lookup did not complete
@@ -270,13 +310,25 @@ abcd in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=ten-1.test.ex
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=ten-1.test.ex
+checking local_parts
+abcd in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for abcd@ten-1.test.ex
   domain = ten-1.test.ex
 calling lookuphost router
 lookuphost router called for abcd@ten-1.test.ex
   domain = ten-1.test.ex
+ten-1.test.ex in "*"? yes (matched "*")
 DNS lookup of ten-1.test.ex (MX) using fakens
 DNS lookup of ten-1.test.ex (MX) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of ten-1.test.ex (MX) gave NO_DATA
 returning DNS_NODATA
 DNS lookup of ten-1.test.ex (MX) gave NO_DATA
 returning DNS_NODATA
+faking res_search(MX) response length as 65535
+ writing neg-cache entry for ten-1.test.ex-MX-xxxx, ttl 3000
+ten-1.test.ex (MX resp) DNSSEC
 DNS lookup of ten-1.test.ex (A) using fakens
 DNS lookup of ten-1.test.ex (A) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
@@ -309,14 +361,19 @@ useryz router called for usery@test.fail.dns
   domain = test.fail.dns
 route_item = * $domain bydns
 test.fail.dns in "*"? yes (matched "*")
   domain = test.fail.dns
 route_item = * $domain bydns
 test.fail.dns in "*"? yes (matched "*")
-original list of hosts = "$domain" options = bydns
-expanded list of hosts = "test.fail.dns" options = bydns
+original list of hosts = '$domain' options = 'bydns'
+expanded list of hosts = 'test.fail.dns' options = 'bydns'
 set transport smtp
 finding IP address for test.fail.dns
 doing DNS lookup
 set transport smtp
 finding IP address for test.fail.dns
 doing DNS lookup
-Return from DNS lookup of test.fail.dns (A) faked for testing
+test.fail.dns in "*"? yes (matched "*")
+DNS lookup of test.fail.dns (A) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of test.fail.dns (A) gave NO_RECOVERY
 returning DNS_FAIL
 DNS lookup of test.fail.dns (A) gave NO_RECOVERY
 returning DNS_FAIL
+ writing neg-cache entry for test.fail.dns-A-xxxx, ttl -1
 useryz router: defer for usery@test.fail.dns
   message: host lookup for test.fail.dns did not complete (DNS timeout?)
 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
 useryz router: defer for usery@test.fail.dns
   message: host lookup for test.fail.dns did not complete (DNS timeout?)
 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
@@ -339,10 +396,11 @@ useryz router called for userz@test.fail.dns
   domain = test.fail.dns
 route_item = * $domain bydns
 test.fail.dns in "*"? yes (matched "*")
   domain = test.fail.dns
 route_item = * $domain bydns
 test.fail.dns in "*"? yes (matched "*")
-original list of hosts = "$domain" options = bydns
-expanded list of hosts = "test.fail.dns" options = bydns
+original list of hosts = '$domain' options = 'bydns'
+expanded list of hosts = 'test.fail.dns' options = 'bydns'
 finding IP address for test.fail.dns
 doing DNS lookup
 finding IP address for test.fail.dns
 doing DNS lookup
+test.fail.dns in "*"? yes (matched "*")
 DNS lookup of test.fail.dns-A: using cached value DNS_FAIL
 useryz router: defer for userz@test.fail.dns
   message: host lookup for test.fail.dns did not complete (DNS timeout?)
 DNS lookup of test.fail.dns-A: using cached value DNS_FAIL
 useryz router: defer for userz@test.fail.dns
   message: host lookup for test.fail.dns did not complete (DNS timeout?)
@@ -364,11 +422,17 @@ xyz in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=xyz domain=ten-1.test.ex
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=xyz domain=ten-1.test.ex
+checking local_parts
+xyz in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for xyz@ten-1.test.ex
   domain = ten-1.test.ex
 calling lookuphost router
 lookuphost router called for xyz@ten-1.test.ex
   domain = ten-1.test.ex
+ten-1.test.ex in "*"? yes (matched "*")
 DNS lookup of ten-1.test.ex-MX: using cached value DNS_NODATA
 DNS lookup of ten-1.test.ex (A) using fakens
 DNS lookup of ten-1.test.ex-MX: using cached value DNS_NODATA
 DNS lookup of ten-1.test.ex (A) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
@@ -381,15 +445,13 @@ routed by lookuphost router
   transport: smtp
   host ten-1.test.ex [V4NET.0.0.1]
 search_tidyup called
   transport: smtp
   host ten-1.test.ex [V4NET.0.0.1]
 search_tidyup called
->>>>>>>>>>>>>>>> Exim pid=pppp terminating with rc=1 >>>>>>>>>>>>>>>>
+>>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=1 >>>>>>>>>>>>>>>>
 Exim version x.yz ....
 changed uid/gid: forcing real = effective
   uid=uuuu gid=CALLER_GID pid=pppp
 configuration file is TESTSUITE/test-config
 admin user
 Exim version x.yz ....
 changed uid/gid: forcing real = effective
   uid=uuuu gid=CALLER_GID pid=pppp
 configuration file is TESTSUITE/test-config
 admin user
-DSN: srv propagating DSN
-DSN: useryz propagating DSN
-DSN: lookuphost propagating DSN
+dropping to exim gid; retaining priv uid
 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
 sender address = CALLER@myhost.test.ex
 Address testing: uid=uuuu gid=EXIM_GID euid=uuuu egid=EXIM_GID
 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
 sender address = CALLER@myhost.test.ex
 Address testing: uid=uuuu gid=EXIM_GID euid=uuuu egid=EXIM_GID
@@ -411,12 +473,20 @@ userx in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=userx domain=nonexist.test.ex
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=userx domain=nonexist.test.ex
+checking local_parts
+userx in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for userx@nonexist.test.ex
   domain = nonexist.test.ex
 calling lookuphost router
 lookuphost router called for userx@nonexist.test.ex
   domain = nonexist.test.ex
+nonexist.test.ex in "*"? yes (matched "*")
 DNS lookup of nonexist.test.ex (MX) using fakens
 DNS lookup of nonexist.test.ex (MX) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of nonexist.test.ex (MX) gave HOST_NOT_FOUND
 returning DNS_NOMATCH
 DNS lookup of nonexist.test.ex (MX) gave HOST_NOT_FOUND
 returning DNS_NOMATCH
+faking res_search(MX) response length as 65535
+ writing neg-cache entry for nonexist.test.ex-MX-xxxx, ttl 3000
 lookuphost router declined for userx@nonexist.test.ex
 "more" is false: skipping remaining routers
 no more routers
 lookuphost router declined for userx@nonexist.test.ex
 "more" is false: skipping remaining routers
 no more routers
@@ -438,9 +508,12 @@ abcd in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=nonexist.test.ex
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=nonexist.test.ex
+checking local_parts
+abcd in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for abcd@nonexist.test.ex
   domain = nonexist.test.ex
 calling lookuphost router
 lookuphost router called for abcd@nonexist.test.ex
   domain = nonexist.test.ex
+nonexist.test.ex in "*"? yes (matched "*")
 DNS lookup of nonexist.test.ex-MX: using cached value DNS_NOMATCH
 lookuphost router declined for abcd@nonexist.test.ex
 "more" is false: skipping remaining routers
 DNS lookup of nonexist.test.ex-MX: using cached value DNS_NOMATCH
 lookuphost router declined for abcd@nonexist.test.ex
 "more" is false: skipping remaining routers
@@ -463,13 +536,25 @@ abcd in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=ten-1.test.ex
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=abcd domain=ten-1.test.ex
+checking local_parts
+abcd in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for abcd@ten-1.test.ex
   domain = ten-1.test.ex
 calling lookuphost router
 lookuphost router called for abcd@ten-1.test.ex
   domain = ten-1.test.ex
+ten-1.test.ex in "*"? yes (matched "*")
 DNS lookup of ten-1.test.ex (MX) using fakens
 DNS lookup of ten-1.test.ex (MX) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of ten-1.test.ex (MX) gave NO_DATA
 returning DNS_NODATA
 DNS lookup of ten-1.test.ex (MX) gave NO_DATA
 returning DNS_NODATA
+faking res_search(MX) response length as 65535
+ writing neg-cache entry for ten-1.test.ex-MX-xxxx, ttl 3000
+ten-1.test.ex (MX resp) DNSSEC
 DNS lookup of ten-1.test.ex (A) using fakens
 DNS lookup of ten-1.test.ex (A) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
@@ -502,14 +587,20 @@ useryz router called for usery@nonexist.test.ex
   domain = nonexist.test.ex
 route_item = * $domain bydns
 nonexist.test.ex in "*"? yes (matched "*")
   domain = nonexist.test.ex
 route_item = * $domain bydns
 nonexist.test.ex in "*"? yes (matched "*")
-original list of hosts = "$domain" options = bydns
-expanded list of hosts = "nonexist.test.ex" options = bydns
+original list of hosts = '$domain' options = 'bydns'
+expanded list of hosts = 'nonexist.test.ex' options = 'bydns'
 set transport smtp
 finding IP address for nonexist.test.ex
 doing DNS lookup
 set transport smtp
 finding IP address for nonexist.test.ex
 doing DNS lookup
+nonexist.test.ex in "*"? yes (matched "*")
 DNS lookup of nonexist.test.ex (A) using fakens
 DNS lookup of nonexist.test.ex (A) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of nonexist.test.ex (A) gave HOST_NOT_FOUND
 returning DNS_NOMATCH
 DNS lookup of nonexist.test.ex (A) gave HOST_NOT_FOUND
 returning DNS_NOMATCH
+faking res_search(A) response length as 65535
+ writing neg-cache entry for nonexist.test.ex-A-xxxx, ttl 3000
 useryz router: defer for usery@nonexist.test.ex
   message: lookup of host "nonexist.test.ex" failed in useryz router
 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
 useryz router: defer for usery@nonexist.test.ex
   message: lookup of host "nonexist.test.ex" failed in useryz router
 >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
@@ -532,10 +623,11 @@ useryz router called for userz@nonexist.test.ex
   domain = nonexist.test.ex
 route_item = * $domain bydns
 nonexist.test.ex in "*"? yes (matched "*")
   domain = nonexist.test.ex
 route_item = * $domain bydns
 nonexist.test.ex in "*"? yes (matched "*")
-original list of hosts = "$domain" options = bydns
-expanded list of hosts = "nonexist.test.ex" options = bydns
+original list of hosts = '$domain' options = 'bydns'
+expanded list of hosts = 'nonexist.test.ex' options = 'bydns'
 finding IP address for nonexist.test.ex
 doing DNS lookup
 finding IP address for nonexist.test.ex
 doing DNS lookup
+nonexist.test.ex in "*"? yes (matched "*")
 DNS lookup of nonexist.test.ex-A: using cached value DNS_NOMATCH
 useryz router: defer for userz@nonexist.test.ex
   message: lookup of host "nonexist.test.ex" failed in useryz router
 DNS lookup of nonexist.test.ex-A: using cached value DNS_NOMATCH
 useryz router: defer for userz@nonexist.test.ex
   message: lookup of host "nonexist.test.ex" failed in useryz router
@@ -557,11 +649,17 @@ xyz in "usery:userz"? no (end of list)
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=xyz domain=ten-1.test.ex
 useryz router skipped: local_parts mismatch
 --------> lookuphost router <--------
 local_part=xyz domain=ten-1.test.ex
+checking local_parts
+xyz in "!userd"? yes (end of list)
 calling lookuphost router
 lookuphost router called for xyz@ten-1.test.ex
   domain = ten-1.test.ex
 calling lookuphost router
 lookuphost router called for xyz@ten-1.test.ex
   domain = ten-1.test.ex
+ten-1.test.ex in "*"? yes (matched "*")
 DNS lookup of ten-1.test.ex-MX: using cached value DNS_NODATA
 DNS lookup of ten-1.test.ex (A) using fakens
 DNS lookup of ten-1.test.ex-MX: using cached value DNS_NODATA
 DNS lookup of ten-1.test.ex (A) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
 DNS lookup of ten-1.test.ex (A) succeeded
 fully qualified name = ten-1.test.ex
 ten-1.test.ex V4NET.0.0.1 mx=-1 sort=xx 
@@ -574,15 +672,13 @@ routed by lookuphost router
   transport: smtp
   host ten-1.test.ex [V4NET.0.0.1]
 search_tidyup called
   transport: smtp
   host ten-1.test.ex [V4NET.0.0.1]
 search_tidyup called
->>>>>>>>>>>>>>>> Exim pid=pppp terminating with rc=2 >>>>>>>>>>>>>>>>
+>>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=2 >>>>>>>>>>>>>>>>
 Exim version x.yz ....
 changed uid/gid: forcing real = effective
   uid=uuuu gid=CALLER_GID pid=pppp
 configuration file is TESTSUITE/test-config
 admin user
 Exim version x.yz ....
 changed uid/gid: forcing real = effective
   uid=uuuu gid=CALLER_GID pid=pppp
 configuration file is TESTSUITE/test-config
 admin user
-DSN: srv propagating DSN
-DSN: useryz propagating DSN
-DSN: lookuphost propagating DSN
+dropping to exim gid; retaining priv uid
 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
 sender address = CALLER@myhost.test.ex
 Address testing: uid=uuuu gid=EXIM_GID euid=uuuu egid=EXIM_GID
 originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
 sender address = CALLER@myhost.test.ex
 Address testing: uid=uuuu gid=EXIM_GID euid=uuuu egid=EXIM_GID
@@ -599,10 +695,15 @@ srv in "^srv"? yes (matched "^srv")
 calling srv router
 srv router called for srv@test.again.dns
   domain = test.again.dns
 calling srv router
 srv router called for srv@test.again.dns
   domain = test.again.dns
-Return from DNS lookup of _smtp._tcp.test.again.dns (SRV) faked for testing
+test.again.dns in "*"? yes (matched "*")
+DNS lookup of _smtp._tcp.test.again.dns (SRV) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of _smtp._tcp.test.again.dns (SRV) gave TRY_AGAIN
 _smtp._tcp.test.again.dns in dns_again_means_nonexist? no (option unset)
 returning DNS_AGAIN
 DNS lookup of _smtp._tcp.test.again.dns (SRV) gave TRY_AGAIN
 _smtp._tcp.test.again.dns in dns_again_means_nonexist? no (option unset)
 returning DNS_AGAIN
+ writing neg-cache entry for _smtp._tcp.test.again.dns-SRV-xxxx, ttl -1
 test.again.dns in "test.fail.dns"? no (end of list)
 srv router: defer for srv@test.again.dns
   message: host lookup did not complete
 test.again.dns in "test.fail.dns"? no (end of list)
 srv router: defer for srv@test.again.dns
   message: host lookup did not complete
@@ -619,20 +720,126 @@ srv in "^srv"? yes (matched "^srv")
 calling srv router
 srv router called for srv@test.fail.dns
   domain = test.fail.dns
 calling srv router
 srv router called for srv@test.fail.dns
   domain = test.fail.dns
-Return from DNS lookup of _smtp._tcp.test.fail.dns (SRV) faked for testing
+test.fail.dns in "*"? yes (matched "*")
+DNS lookup of _smtp._tcp.test.fail.dns (SRV) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of _smtp._tcp.test.fail.dns (SRV) gave NO_RECOVERY
 returning DNS_FAIL
 DNS lookup of _smtp._tcp.test.fail.dns (SRV) gave NO_RECOVERY
 returning DNS_FAIL
+ writing neg-cache entry for _smtp._tcp.test.fail.dns-SRV-xxxx, ttl -1
 test.fail.dns in "test.fail.dns"? yes (matched "test.fail.dns")
 DNS_FAIL treated as DNS_NODATA (domain in srv_fail_domains)
 test.fail.dns in "test.fail.dns"? yes (matched "test.fail.dns")
 DNS_FAIL treated as DNS_NODATA (domain in srv_fail_domains)
-Return from DNS lookup of test.fail.dns (MX) faked for testing
+DNS lookup of test.fail.dns (MX) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of test.fail.dns (MX) gave NO_RECOVERY
 returning DNS_FAIL
 DNS lookup of test.fail.dns (MX) gave NO_RECOVERY
 returning DNS_FAIL
+ writing neg-cache entry for test.fail.dns-MX-xxxx, ttl -1
 test.fail.dns in "test.fail.dns"? yes (matched "test.fail.dns")
 DNS_FAIL treated as DNS_NODATA (domain in mx_fail_domains)
 test.fail.dns in "test.fail.dns"? yes (matched "test.fail.dns")
 DNS_FAIL treated as DNS_NODATA (domain in mx_fail_domains)
-Return from DNS lookup of test.fail.dns (A) faked for testing
+DNS lookup of test.fail.dns (A) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
 DNS lookup of test.fail.dns (A) gave NO_RECOVERY
 returning DNS_FAIL
 DNS lookup of test.fail.dns (A) gave NO_RECOVERY
 returning DNS_FAIL
+ writing neg-cache entry for test.fail.dns-A-xxxx, ttl -1
 srv router: defer for srv@test.fail.dns
   message: host lookup did not complete
 search_tidyup called
 srv router: defer for srv@test.fail.dns
   message: host lookup did not complete
 search_tidyup called
->>>>>>>>>>>>>>>> Exim pid=pppp terminating with rc=1 >>>>>>>>>>>>>>>>
+>>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=1 >>>>>>>>>>>>>>>>
+Exim version x.yz ....
+changed uid/gid: forcing real = effective
+  uid=uuuu gid=CALLER_GID pid=pppp
+configuration file is TESTSUITE/test-config
+admin user
+dropping to exim gid; retaining priv uid
+originator: uid=CALLER_UID gid=CALLER_GID login=CALLER name=CALLER_NAME
+sender address = CALLER@myhost.test.ex
+Address testing: uid=uuuu gid=EXIM_GID euid=uuuu egid=EXIM_GID
+>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
+Testing userx@nonexist.example.com
+>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
+Considering userx@nonexist.example.com
+>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
+routing userx@nonexist.example.com
+--------> srv router <--------
+local_part=userx domain=nonexist.example.com
+checking local_parts
+userx in "^srv"? no (end of list)
+srv router skipped: local_parts mismatch
+--------> useryz router <--------
+local_part=userx domain=nonexist.example.com
+checking local_parts
+userx in "usery:userz"? no (end of list)
+useryz router skipped: local_parts mismatch
+--------> lookuphost router <--------
+local_part=userx domain=nonexist.example.com
+checking local_parts
+userx in "!userd"? yes (end of list)
+calling lookuphost router
+lookuphost router called for userx@nonexist.example.com
+  domain = nonexist.example.com
+nonexist.example.com in "*"? yes (matched "*")
+DNS lookup of nonexist.example.com (MX) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
+DNS lookup of nonexist.example.com (MX) gave HOST_NOT_FOUND
+returning DNS_NOMATCH
+faking res_search(MX) response length as 65535
+ writing neg-cache entry for nonexist.example.com-MX-xxxx, ttl 2
+lookuphost router declined for userx@nonexist.example.com
+"more" is false: skipping remaining routers
+no more routers
+>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
+Testing userd@nonexist.example.com
+>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
+Considering userd@nonexist.example.com
+>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
+routing userd@nonexist.example.com
+--------> srv router <--------
+local_part=userd domain=nonexist.example.com
+checking local_parts
+userd in "^srv"? no (end of list)
+srv router skipped: local_parts mismatch
+--------> useryz router <--------
+local_part=userd domain=nonexist.example.com
+checking local_parts
+userd in "usery:userz"? no (end of list)
+useryz router skipped: local_parts mismatch
+--------> lookuphost router <--------
+local_part=userd domain=nonexist.example.com
+checking local_parts
+userd in "!userd"? no (matched "!userd")
+lookuphost router skipped: local_parts mismatch
+--------> delay router <--------
+local_part=userd domain=nonexist.example.com
+checking "condition" "${acl {delay}}"...
+  using ACL "delay"
+  processing "accept" (TESTSUITE/test-config 18)
+  check delay = 3s
+  delay modifier requests 3-second delay
+    message: y
+  accept: condition test succeeded in ACL "delay"
+  end of ACL "delay": ACCEPT
+calling delay router
+delay router called for userd@nonexist.example.com
+  domain = nonexist.example.com
+nonexist.example.com in "*"? yes (matched "*")
+DNS lookup of nonexist.example.com-MX: cached value DNS_NOMATCH past valid time
+DNS lookup of nonexist.example.com (MX) using fakens
+fresh-exec forking for child-open
+postfork: child-open
+fresh-exec forked for child-open: npppp
+DNS lookup of nonexist.example.com (MX) gave HOST_NOT_FOUND
+returning DNS_NOMATCH
+faking res_search(MX) response length as 65535
+ update neg-cache entry for nonexist.example.com-MX-xxxx, ttl 2
+delay router declined for userd@nonexist.example.com
+"more" is false: skipping remaining routers
+no more routers
+search_tidyup called
+>>>>>>>>>>>>>>>> Exim pid=pppp (main) terminating with rc=2 >>>>>>>>>>>>>>>>