"forward" system test fails intermittently

The last check in the test, "checking that priming queries are not forwarded", can rarely trigger a false positive. See https://gitlab.isc.org/isc-projects/bind9/-/jobs/181625 for an example. The problem is that dig may return before ns1 logs the priming query:

---

• ns7/named.run:

22-Feb-2019 06:51:21.336 client @0x7fa44003dc10 10.53.0.1#39681 (txt.example1): query (cache) 'txt.example1/TXT/IN' approved
...
22-Feb-2019 06:51:21.337 res 0x7fa455437020: priming
22-Feb-2019 06:51:21.337 fetch: ./NS
...
22-Feb-2019 06:51:21.337 socket 0x7fa45543a310 10.53.0.7#43075: bound
22-Feb-2019 06:51:21.337 socket 0x7fa45543a600 10.53.0.7#51763: bound
...
...
22-Feb-2019 06:51:21.337 sending packet to 10.53.0.1#8600
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id:  22324
;; flags:; QUESTION: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 512
; COOKIE: 4d1e44ce6bd38bf7
;; QUESTION SECTION:
;.                              IN      NS


22-Feb-2019 06:51:21.337 sending packet to 10.53.0.4#8600
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id:  14354
;; flags: rd; QUESTION: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 512
; COOKIE: 2f66027d9adee561
;; QUESTION SECTION:
;txt.example1.                  IN      TXT
...
22-Feb-2019 06:51:21.338 received packet from 10.53.0.4#8600
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id:  14354
;; flags: qr rd ra; QUESTION: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
; COOKIE: 2f66027d9adee56118fc22405c6f9be94038c7c62a19ec15
;; QUESTION SECTION:
;txt.example1.                  IN      TXT

;; ANSWER SECTION:
;txt.example1.          300     IN      TXT     "forwarded"
...
22-Feb-2019 06:51:21.338 client @0x7fa44003dc10 10.53.0.1#39681 (txt.example1): send
22-Feb-2019 06:51:21.338 client @0x7fa44003dc10 10.53.0.1#39681 (txt.example1): sendto
22-Feb-2019 06:51:21.338 client @0x7fa44003dc10 10.53.0.1#39681 (txt.example1): senddone
22-Feb-2019 06:51:21.338 client @0x7fa44003dc10 10.53.0.1#39681 (txt.example1): next
22-Feb-2019 06:51:21.338 client @0x7fa44003dc10 10.53.0.1#39681 (txt.example1): ns_client_detach: ref = 0
22-Feb-2019 06:51:21.338 client @0x7fa44003dc10 10.53.0.1#39681 (txt.example1): endrequest
...
22-Feb-2019 06:51:21.349 received packet from 10.53.0.1#8600
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id:  22324
;; flags: qr aa; QUESTION: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 2
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags: do; udp: 4096
; COOKIE: 4d1e44ce6bd38bf769a6f34b5c6f9be9b821635b54edb75d
;; QUESTION SECTION:
;.                              IN      NS

;; ANSWER SECTION:
;.                      300     IN      NS      a.root-servers.nil.

;; ADDITIONAL SECTION:
;a.root-servers.nil.    300     IN      A       10.53.0.1

• ns1/named.run:

22-Feb-2019 06:51:21.348 client @0x7f696800ee90 10.53.0.7#51763 (.): query './NS/IN' approved

---

Thus, if:

sent=`grep "10.53.0.7#.* (.): query '\./NS/IN' approved" ns1/named.run | wc -l`

manages to complete before that line appears in ns1/named.run, a false positive will be triggered.

@wpk, since you wrote the test and it is a fairly recent addition, please fix it? :)