From 444163417b289354b53d4708760f31d947ac6fd1 Mon Sep 17 00:00:00 2001 From: Jeremy Harris Date: Thu, 24 Oct 2019 12:58:19 +0100 Subject: [PATCH] Testsuite: handle slow test-hosts more intelligently --- src/src/deliver.c | 46 ++++++++++++++++++++---------------- src/src/functions.h | 1 + src/src/queue.c | 4 ++-- src/src/spool_in.c | 6 ++++- test/confs/0206 | 4 ++-- test/confs/0618 | 4 ++-- test/log/0618 | 18 ++------------ test/rejectlog/0618 | 2 -- test/scripts/0000-Basic/0206 | 8 +++---- test/scripts/0000-Basic/0618 | 8 +++---- 10 files changed, 48 insertions(+), 53 deletions(-) diff --git a/src/src/deliver.c b/src/src/deliver.c index 0055ad481..34990b71e 100644 --- a/src/src/deliver.c +++ b/src/src/deliver.c @@ -5474,6 +5474,26 @@ fprintf(f, "Action: %s\n" } + +/* When running in the test harness, there's an option that allows us to +fudge this time so as to get repeatability of the tests. Take the first +time off the list. In queue runs, the list pointer gets updated in the +calling process. */ + +int +test_harness_fudged_queue_time(int actual_time) +{ +int qt; +if ( f.running_in_test_harness && *fudged_queue_times + && (qt = readconf_readtime(fudged_queue_times, '/', FALSE)) >= 0) + { + DEBUG(D_deliver) debug_printf("fudged queue_times = %s\n", + fudged_queue_times); + return qt; + } +return actual_time; +} + /************************************************* * Deliver one message * *************************************************/ @@ -6164,7 +6184,8 @@ if (process_recipients != RECIP_IGNORE) new->onetime_parent = recipients_list[r->pno].address; /* If DSN support is enabled, set the dsn flags and the original receipt - to be passed on to other DSN enabled MTAs */ + to be passed on to other DSN enabled MTAs */ + new->dsn_flags = r->dsn_flags & rf_dsnflags; new->dsn_orcpt = r->orcpt; DEBUG(D_deliver) debug_printf("DSN: set orcpt: %s flags: 0x%x\n", @@ -7284,10 +7305,9 @@ for (address_item * a = addr_succeed; a; a = a->next) ); /* send report if next hop not DSN aware or a router flagged "last DSN hop" - and a report was requested */ - if ( ( a->dsn_aware != dsn_support_yes - || a->dsn_flags & rf_dsnlasthop - ) + and a report was requested */ + + if ( (a->dsn_aware != dsn_support_yes || a->dsn_flags & rf_dsnlasthop) && a->dsn_flags & rf_notify_success ) { @@ -8131,21 +8151,7 @@ else if (addr_defer != (address_item *)(+1)) int show_time; int queue_time = time(NULL) - received_time.tv_sec; - /* When running in the test harness, there's an option that allows us to - fudge this time so as to get repeatability of the tests. Take the first - time off the list. In queue runs, the list pointer gets updated in the - calling process. */ - - if (f.running_in_test_harness && fudged_queue_times[0] != 0) - { - int qt = readconf_readtime(fudged_queue_times, '/', FALSE); - if (qt >= 0) - { - DEBUG(D_deliver) debug_printf("fudged queue_times = %s\n", - fudged_queue_times); - queue_time = qt; - } - } + queue_time = test_harness_fudged_queue_time(queue_time); /* See how many warnings we should have sent by now */ diff --git a/src/src/functions.h b/src/src/functions.h index 35600ba2a..8905d02a2 100644 --- a/src/src/functions.h +++ b/src/src/functions.h @@ -539,6 +539,7 @@ extern int strcmpic(const uschar *, const uschar *); extern int strncmpic(const uschar *, const uschar *, int); extern uschar *strstric(uschar *, uschar *, BOOL); +extern int test_harness_fudged_queue_time(int); #ifdef EXIM_TFO_PROBE extern void tfo_probe(void); #endif diff --git a/src/src/queue.c b/src/src/queue.c index d8c160a3a..670f51c45 100644 --- a/src/src/queue.c +++ b/src/src/queue.c @@ -664,8 +664,8 @@ for (int i = queue_run_in_order ? -1 : 0; if (f.running_in_test_harness && !f.queue_2stage) { - uschar *fqtnext = Ustrchr(fudged_queue_times, '/'); - if (fqtnext != NULL) fudged_queue_times = fqtnext + 1; + uschar * fqtnext = Ustrchr(fudged_queue_times, '/'); + if (fqtnext) fudged_queue_times = fqtnext + 1; } } /* End loop for list of messages */ diff --git a/src/src/spool_in.c b/src/src/spool_in.c index f393d4d3e..7c60a12a0 100644 --- a/src/src/spool_in.c +++ b/src/src/spool_in.c @@ -423,12 +423,16 @@ if (sscanf(CS big_buffer, TIME_T_FMT " %d", &received_time.tv_sec, &warning_coun received_time.tv_usec = 0; message_age = time(NULL) - received_time.tv_sec; +#ifndef COMPILE_UTILITY +if (f.running_in_test_harness) + message_age = test_harness_fudged_queue_time(message_age); +#endif #ifndef COMPILE_UTILITY DEBUG(D_deliver) debug_printf("user=%s uid=%ld gid=%ld sender=%s\n", originator_login, (long int)originator_uid, (long int)originator_gid, sender_address); -#endif /* COMPILE_UTILITY */ +#endif /* Now there may be a number of optional lines, each starting with "-". If you add a new setting here, make sure you set the default above. diff --git a/test/confs/0206 b/test/confs/0206 index 628d2ec4d..7b3180dec 100644 --- a/test/confs/0206 +++ b/test/confs/0206 @@ -7,8 +7,8 @@ primary_hostname = myhost.test.ex # ----- Main settings ----- -ignore_bounce_errors_after = 2s -timeout_frozen_after = 5s +ignore_bounce_errors_after = 4s +timeout_frozen_after = 10s queue_run_in_order diff --git a/test/confs/0618 b/test/confs/0618 index db4bd3002..a461065e5 100644 --- a/test/confs/0618 +++ b/test/confs/0618 @@ -11,7 +11,7 @@ primary_hostname = myhost.test.ex .ifdef OPT dsn_advertise_hosts = * .endif -delay_warning = 3s : 24h +delay_warning = 6s : 24h accept_8bitmime = false pipelining_advertise_hosts = : @@ -89,5 +89,5 @@ tofile: begin retry -* * F,1m,3s +* * F,2m,10s # End diff --git a/test/log/0618 b/test/log/0618 index a572e11f3..ad992d9a2 100644 --- a/test/log/0618 +++ b/test/log/0618 @@ -56,21 +56,9 @@ 1999-03-02 09:44:33 End queue run: pid=pppp 1999-03-02 09:44:33 playout 1999-03-02 09:44:33 Start queue run: pid=pppp -1999-03-02 09:44:33 10HmbB-0005vi-00 event tcp:connect -1999-03-02 09:44:33 10HmbB-0005vi-00 event smtp:connect -1999-03-02 09:44:33 10HmbB-0005vi-00 event smtp:ehlo -1999-03-02 09:44:33 10HmbB-0005vi-00 event msg:rcpt:host:defer -1999-03-02 09:44:33 10HmbB-0005vi-00 event msg:rcpt:defer -1999-03-02 09:44:33 10HmbB-0005vi-00 event tcp:close -1999-03-02 09:44:33 10HmbB-0005vi-00 == rmt_defer@test.ex R=r2 T=smtp defer (-44) H=127.0.0.1 [127.0.0.1]: SMTP error from remote mail server after RCPT TO:: 451 Temporary local problem - please try later +1999-03-02 09:44:33 10HmbB-0005vi-00 == rmt_defer@test.ex routing defer (-51): retry time not reached 1999-03-02 09:44:33 10HmbD-0005vi-00 <= <> R=10HmbB-0005vi-00 U=EXIMUSER P=local S=sss for c@dump.ex -1999-03-02 09:44:33 10HmbC-0005vi-00 event tcp:connect -1999-03-02 09:44:33 10HmbC-0005vi-00 event smtp:connect -1999-03-02 09:44:33 10HmbC-0005vi-00 event smtp:ehlo -1999-03-02 09:44:33 10HmbC-0005vi-00 event msg:rcpt:host:defer -1999-03-02 09:44:33 10HmbC-0005vi-00 event msg:rcpt:defer -1999-03-02 09:44:33 10HmbC-0005vi-00 event tcp:close -1999-03-02 09:44:33 10HmbC-0005vi-00 == rmt_defer@test.ex R=r2 T=smtp defer (-44) H=127.0.0.1 [127.0.0.1]: SMTP error from remote mail server after RCPT TO:: 451 Temporary local problem - please try later +1999-03-02 09:44:33 10HmbC-0005vi-00 == rmt_defer@test.ex routing defer (-51): retry time not reached 1999-03-02 09:44:33 End queue run: pid=pppp 1999-03-02 09:44:33 10HmbB-0005vi-00 event msg:fail:internal 1999-03-02 09:44:33 10HmbB-0005vi-00 event msg:complete @@ -112,7 +100,5 @@ 1999-03-02 09:44:33 H=localhost (myhost.test.ex) [127.0.0.1] F= temporarily rejected RCPT 1999-03-02 09:44:33 10HmbC-0005vi-00 <= d@dump.ex H=(testclient) [ip4.ip4.ip4.ip4] P=esmtp S=sss for rmt_defer@test.ex 1999-03-02 09:44:33 H=localhost (myhost.test.ex) [127.0.0.1] F= temporarily rejected RCPT -1999-03-02 09:44:33 H=localhost (myhost.test.ex) [127.0.0.1] F= temporarily rejected RCPT -1999-03-02 09:44:33 H=localhost (myhost.test.ex) [127.0.0.1] F= temporarily rejected RCPT 1999-03-02 09:44:33 10HmbE-0005vi-00 <= e@dump.ex H=(testclient) [ip4.ip4.ip4.ip4] P=esmtp S=sss for rmt_reject@test.ex 1999-03-02 09:44:33 H=localhost (myhost.test.ex) [127.0.0.1] F= rejected RCPT diff --git a/test/rejectlog/0618 b/test/rejectlog/0618 index 3b9bea1a0..555a47591 100644 --- a/test/rejectlog/0618 +++ b/test/rejectlog/0618 @@ -3,6 +3,4 @@ 1999-03-02 09:44:33 H=localhost (myhost.test.ex) [127.0.0.1] F= rejected RCPT 1999-03-02 09:44:33 H=localhost (myhost.test.ex) [127.0.0.1] F= temporarily rejected RCPT 1999-03-02 09:44:33 H=localhost (myhost.test.ex) [127.0.0.1] F= temporarily rejected RCPT -1999-03-02 09:44:33 H=localhost (myhost.test.ex) [127.0.0.1] F= temporarily rejected RCPT -1999-03-02 09:44:33 H=localhost (myhost.test.ex) [127.0.0.1] F= temporarily rejected RCPT 1999-03-02 09:44:33 H=localhost (myhost.test.ex) [127.0.0.1] F= rejected RCPT diff --git a/test/scripts/0000-Basic/0206 b/test/scripts/0000-Basic/0206 index 64afd8014..2739f29e1 100644 --- a/test/scripts/0000-Basic/0206 +++ b/test/scripts/0000-Basic/0206 @@ -6,11 +6,11 @@ sudo exim -Mf $msg1 **** # now 2 frozen, one of which is a bounce # check that ignore_bounce_errors_after finishes off the frozen bounce (only) -millisleep 2500 -exim -qf +#sleep 5 +exim -Tqt 5s/5s/ -qf **** -sleep 3 +#sleep 6 # check that timeout_frozen_after finishes off the (remaining) frozen -exim -q +exim -Tqt 11s/11s -q **** no_msglog_check diff --git a/test/scripts/0000-Basic/0618 b/test/scripts/0000-Basic/0618 index 13d395f02..69a53c691 100644 --- a/test/scripts/0000-Basic/0618 +++ b/test/scripts/0000-Basic/0618 @@ -76,8 +76,9 @@ exim -q # # Client requests notification of deferral. First time of trying, we get # a defer but queue-time probably has not hit the 1st retry time yet, so no DSN -# will be sent and the message remains queued. Later, after a sleep, we will -# try again. +# will be sent and the message remains queued. Then, claiming time has elapsed, +# we will look again (expecting a delay-DSN to be produced). We won't see a +# retry since the actual retry time has not passed. exim -z defer/delay **** client HOSTIPV4 PORT_D @@ -126,7 +127,6 @@ QUIT **** exim -q **** -sleep 3 # # # @@ -134,7 +134,7 @@ sleep 3 # We should see the notify for c@dump.ex but not d@dump.ex exim -z playout **** -exim -q +exim -Tqt 10s/ -q **** sleep 1 exim -Mrm $msg1 $msg2 -- 2.25.1