Testsuite: when running under the testharness, wait longer for transport process...
authorJeremy Harris <jgh146exb@wizmail.org>
Sat, 19 Oct 2019 10:44:30 +0000 (11:44 +0100)
committerJeremy Harris <jgh146exb@wizmail.org>
Sat, 19 Oct 2019 19:52:36 +0000 (20:52 +0100)
src/src/deliver.c
test/log/5611
test/log/5651
test/stderr/0476

index e228a0bfd7a555f36b26728bf1b936fae9f90d20..0055ad4811525959d479644edc883bad4b303e59 100644 (file)
@@ -5024,9 +5024,10 @@ all pipes, so I do not see a reason to use non-blocking IO here
 
   /* Otherwise, if we are running in the test harness, wait a bit, to let the
   newly created process get going before we create another process. This should
 
   /* Otherwise, if we are running in the test harness, wait a bit, to let the
   newly created process get going before we create another process. This should
-  ensure repeatability in the tests. We only need to wait a tad. */
+  ensure repeatability in the tests. Wait long enough for most cases to complete
+  the transport. */
 
 
-  else testharness_pause_ms(500);
+  else testharness_pause_ms(600);
 
   continue;
 
 
   continue;
 
index 200f32113ebec6e934542ef1297a944c180f1737..1262992b9fb1815859742f38e27a389395cad837 100644 (file)
@@ -2,11 +2,11 @@
 1999-03-02 09:44:33 10HmaX-0005vi-00 => norequire@test.ex R=client T=send_to_server2 H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmaY-0005vi-00"
 1999-03-02 09:44:33 10HmaX-0005vi-00 Completed
 1999-03-02 09:44:33 10HmaZ-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
 1999-03-02 09:44:33 10HmaX-0005vi-00 => norequire@test.ex R=client T=send_to_server2 H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmaY-0005vi-00"
 1999-03-02 09:44:33 10HmaX-0005vi-00 Completed
 1999-03-02 09:44:33 10HmaZ-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
-1999-03-02 09:44:33 10HmaZ-0005vi-00 => nostaple@test.ex R=client T=send_to_server1 H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbA-0005vi-00"
+1999-03-02 09:44:33 10HmbA-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
+1999-03-02 09:44:33 10HmaZ-0005vi-00 => nostaple@test.ex R=client T=send_to_server1 H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbB-0005vi-00"
 1999-03-02 09:44:33 10HmaZ-0005vi-00 Completed
 1999-03-02 09:44:33 10HmaZ-0005vi-00 Completed
-1999-03-02 09:44:33 10HmbB-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
-1999-03-02 09:44:33 10HmbB-0005vi-00 => CALLER@test.ex R=client T=send_to_server3 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbC-0005vi-00"
-1999-03-02 09:44:33 10HmbB-0005vi-00 Completed
+1999-03-02 09:44:33 10HmbA-0005vi-00 => CALLER@test.ex R=client T=send_to_server3 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="/CN=server1.example.com" C="250 OK id=10HmbC-0005vi-00"
+1999-03-02 09:44:33 10HmbA-0005vi-00 Completed
 1999-03-02 09:44:33 10HmbD-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
 1999-03-02 09:44:33 10HmbD-0005vi-00 Received TLS status callback, null content
 1999-03-02 09:44:33 10HmbD-0005vi-00 == CALLER@test.ex R=client T=send_to_server3 defer (-37) H=127.0.0.1 [127.0.0.1]: TLS session: (SSL_connect): error: <<detail omitted>>
 1999-03-02 09:44:33 10HmbD-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
 1999-03-02 09:44:33 10HmbD-0005vi-00 Received TLS status callback, null content
 1999-03-02 09:44:33 10HmbD-0005vi-00 == CALLER@test.ex R=client T=send_to_server3 defer (-37) H=127.0.0.1 [127.0.0.1]: TLS session: (SSL_connect): error: <<detail omitted>>
 1999-03-02 09:44:33 10HmaY-0005vi-00 => :blackhole: <norequire@test.ex> R=server
 1999-03-02 09:44:33 10HmaY-0005vi-00 Completed
 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port PORT_D
 1999-03-02 09:44:33 10HmaY-0005vi-00 => :blackhole: <norequire@test.ex> R=server
 1999-03-02 09:44:33 10HmaY-0005vi-00 Completed
 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port PORT_D
-1999-03-02 09:44:33 10HmbA-0005vi-00 client claims: ocsp status 0 (notreq)
-1999-03-02 09:44:33 10HmbA-0005vi-00 <= CALLER@server1.example.com H=the.local.host.name (server1.example.com) [ip4.ip4.ip4.ip4] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmaZ-0005vi-00@server1.example.com
-1999-03-02 09:44:33 10HmbA-0005vi-00 => :blackhole: <nostaple@test.ex> R=server
-1999-03-02 09:44:33 10HmbA-0005vi-00 Completed
+1999-03-02 09:44:33 10HmbB-0005vi-00 client claims: ocsp status 0 (notreq)
+1999-03-02 09:44:33 10HmbB-0005vi-00 <= CALLER@server1.example.com H=the.local.host.name (server1.example.com) [ip4.ip4.ip4.ip4] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmaZ-0005vi-00@server1.example.com
+1999-03-02 09:44:33 10HmbB-0005vi-00 => :blackhole: <nostaple@test.ex> R=server
+1999-03-02 09:44:33 10HmbB-0005vi-00 Completed
 1999-03-02 09:44:33 10HmbC-0005vi-00 client claims: ocsp status 4 (verified)
 1999-03-02 09:44:33 10HmbC-0005vi-00 client claims: ocsp status 4 (verified)
-1999-03-02 09:44:33 10HmbC-0005vi-00 <= CALLER@server1.example.com H=(helo.data.changed) [127.0.0.1] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmbB-0005vi-00@server1.example.com
+1999-03-02 09:44:33 10HmbC-0005vi-00 <= CALLER@server1.example.com H=(helo.data.changed) [127.0.0.1] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmbA-0005vi-00@server1.example.com
 1999-03-02 09:44:33 10HmbC-0005vi-00 => :blackhole: <CALLER@test.ex> R=server
 1999-03-02 09:44:33 10HmbC-0005vi-00 Completed
 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port PORT_D
 1999-03-02 09:44:33 10HmbC-0005vi-00 => :blackhole: <CALLER@test.ex> R=server
 1999-03-02 09:44:33 10HmbC-0005vi-00 Completed
 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port PORT_D
index 2b2af41c9f9673534c4f81426dc4a734b09c48ad..bcd662f5b8a7bc943f0dafd284b6a43120397ea9 100644 (file)
@@ -2,11 +2,11 @@
 1999-03-02 09:44:33 10HmaX-0005vi-00 => norequire@test.ex R=client T=send_to_server2 H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="CN=server1.example.com" C="250 OK id=10HmaY-0005vi-00"
 1999-03-02 09:44:33 10HmaX-0005vi-00 Completed
 1999-03-02 09:44:33 10HmaZ-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
 1999-03-02 09:44:33 10HmaX-0005vi-00 => norequire@test.ex R=client T=send_to_server2 H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="CN=server1.example.com" C="250 OK id=10HmaY-0005vi-00"
 1999-03-02 09:44:33 10HmaX-0005vi-00 Completed
 1999-03-02 09:44:33 10HmaZ-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
-1999-03-02 09:44:33 10HmaZ-0005vi-00 => nostaple@test.ex R=client T=send_to_server1 H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="CN=server1.example.com" C="250 OK id=10HmbA-0005vi-00"
+1999-03-02 09:44:33 10HmbA-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
+1999-03-02 09:44:33 10HmaZ-0005vi-00 => nostaple@test.ex R=client T=send_to_server1 H=ip4.ip4.ip4.ip4 [ip4.ip4.ip4.ip4] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="CN=server1.example.com" C="250 OK id=10HmbB-0005vi-00"
 1999-03-02 09:44:33 10HmaZ-0005vi-00 Completed
 1999-03-02 09:44:33 10HmaZ-0005vi-00 Completed
-1999-03-02 09:44:33 10HmbB-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
-1999-03-02 09:44:33 10HmbB-0005vi-00 => CALLER@test.ex R=client T=send_to_server3 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="CN=server1.example.com" C="250 OK id=10HmbC-0005vi-00"
-1999-03-02 09:44:33 10HmbB-0005vi-00 Completed
+1999-03-02 09:44:33 10HmbA-0005vi-00 => CALLER@test.ex R=client T=send_to_server3 H=127.0.0.1 [127.0.0.1] X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=yes DN="CN=server1.example.com" C="250 OK id=10HmbC-0005vi-00"
+1999-03-02 09:44:33 10HmbA-0005vi-00 Completed
 1999-03-02 09:44:33 10HmbD-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
 1999-03-02 09:44:33 10HmbD-0005vi-00 == CALLER@test.ex R=client T=send_to_server3 defer (-37) H=127.0.0.1 [127.0.0.1]: TLS session: (certificate status check failed)
 1999-03-02 09:44:33 10HmbE-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
 1999-03-02 09:44:33 10HmbD-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
 1999-03-02 09:44:33 10HmbD-0005vi-00 == CALLER@test.ex R=client T=send_to_server3 defer (-37) H=127.0.0.1 [127.0.0.1]: TLS session: (certificate status check failed)
 1999-03-02 09:44:33 10HmbE-0005vi-00 <= CALLER@server1.example.com U=CALLER P=local S=sss
 1999-03-02 09:44:33 10HmaY-0005vi-00 => :blackhole: <norequire@test.ex> R=server
 1999-03-02 09:44:33 10HmaY-0005vi-00 Completed
 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port PORT_D
 1999-03-02 09:44:33 10HmaY-0005vi-00 => :blackhole: <norequire@test.ex> R=server
 1999-03-02 09:44:33 10HmaY-0005vi-00 Completed
 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port PORT_D
-1999-03-02 09:44:33 10HmbA-0005vi-00 client claims: OCSP status 0 (notreq)
-1999-03-02 09:44:33 10HmbA-0005vi-00 <= CALLER@server1.example.com H=the.local.host.name (server1.example.com) [ip4.ip4.ip4.ip4] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmaZ-0005vi-00@server1.example.com
-1999-03-02 09:44:33 10HmbA-0005vi-00 => :blackhole: <nostaple@test.ex> R=server
-1999-03-02 09:44:33 10HmbA-0005vi-00 Completed
+1999-03-02 09:44:33 10HmbB-0005vi-00 client claims: OCSP status 0 (notreq)
+1999-03-02 09:44:33 10HmbB-0005vi-00 <= CALLER@server1.example.com H=the.local.host.name (server1.example.com) [ip4.ip4.ip4.ip4] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmaZ-0005vi-00@server1.example.com
+1999-03-02 09:44:33 10HmbB-0005vi-00 => :blackhole: <nostaple@test.ex> R=server
+1999-03-02 09:44:33 10HmbB-0005vi-00 Completed
 1999-03-02 09:44:33 10HmbC-0005vi-00 client claims: OCSP status 4 (verified)
 1999-03-02 09:44:33 10HmbC-0005vi-00 client claims: OCSP status 4 (verified)
-1999-03-02 09:44:33 10HmbC-0005vi-00 <= CALLER@server1.example.com H=(helo.data.changed) [127.0.0.1] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmbB-0005vi-00@server1.example.com
+1999-03-02 09:44:33 10HmbC-0005vi-00 <= CALLER@server1.example.com H=(helo.data.changed) [127.0.0.1] P=esmtps X=TLS1.x:ke-RSA-AES256-SHAnnn:xxx CV=no S=sss id=E10HmbA-0005vi-00@server1.example.com
 1999-03-02 09:44:33 10HmbC-0005vi-00 => :blackhole: <CALLER@test.ex> R=server
 1999-03-02 09:44:33 10HmbC-0005vi-00 Completed
 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port PORT_D
 1999-03-02 09:44:33 10HmbC-0005vi-00 => :blackhole: <CALLER@test.ex> R=server
 1999-03-02 09:44:33 10HmbC-0005vi-00 Completed
 1999-03-02 09:44:33 exim x.yz daemon started: pid=pppp, no queue runs, listening for SMTP on port PORT_D
index 140ab775e97b5824cbf90f8e081e5fb7f1d22025..9c6466e9d1a0fc2398a5c0e8e421bf8b203f2e83 100644 (file)
@@ -88,12 +88,12 @@ LOG: MAIN
   H=127.0.0.1 [127.0.0.1] Connection refused
 set_process_info: pppp delivering 10HmaZ-0005vi-00: just tried 127.0.0.1 [127.0.0.1]:PORT_S for CALLER@the.local.host.name: result DEFER
 added retry item for T:127.0.0.1:127.0.0.1:1224: errno=dd more_errno=dd,A flags=2
   H=127.0.0.1 [127.0.0.1] Connection refused
 set_process_info: pppp delivering 10HmaZ-0005vi-00: just tried 127.0.0.1 [127.0.0.1]:PORT_S for CALLER@the.local.host.name: result DEFER
 added retry item for T:127.0.0.1:127.0.0.1:1224: errno=dd more_errno=dd,A flags=2
-set_process_info: pppp delivering 10HmaZ-0005vi-00: waiting for a remote delivery subprocess to finish
 all IP addresses skipped or deferred at least one address
 updating wait-t1 database
 added to list for 127.0.0.1
 Leaving t1 transport
 set_process_info: pppp delivering 10HmaZ-0005vi-00 (just run t1 for CALLER@the.local.host.name in subprocess)
 all IP addresses skipped or deferred at least one address
 updating wait-t1 database
 added to list for 127.0.0.1
 Leaving t1 transport
 set_process_info: pppp delivering 10HmaZ-0005vi-00 (just run t1 for CALLER@the.local.host.name in subprocess)
+set_process_info: pppp delivering 10HmaZ-0005vi-00: waiting for a remote delivery subprocess to finish
 set_process_info: pppp delivering 10HmaZ-0005vi-00
 LOG: MAIN
   == CALLER@the.local.host.name R=r1 T=t1 defer (dd): Connection refused
 set_process_info: pppp delivering 10HmaZ-0005vi-00
 LOG: MAIN
   == CALLER@the.local.host.name R=r1 T=t1 defer (dd): Connection refused