views system test has wrong test strings for reload completion.
We should be looking for "all zones loaded" rather than "reloading zones succeeded". The later results in timing issues.
S:views/:Wed 28 Feb 2018 17:07:34 AEDT T:views/:1:A A:views/:System test views/ I:views/:PORTRANGE:5300 - 5399 I:views:fetching a.example from ns2's initial configuration I:views:fetching a.example from ns3's initial configuration I:views:copying in new configurations for ns2 and ns3 I:views:reloading ns2 and ns3 with rndc I:views:ns2 server reload successful I:views:ns3 server reload successful I:views:wait for reload ns2/named.run 28-Feb-2018 17:07:37.082 zone_settimer: zone example/IN/internal: enter 28-Feb-2018 17:07:37.082 zone_settimer: zone example/IN/internal: settimer inactive 28-Feb-2018 17:07:37.119 zone_settimer: zone example/IN/external: enter 28-Feb-2018 17:07:37.120 zone_settimer: zone example/IN/external: settimer inactive 28-Feb-2018 17:07:37.203 zone example/IN: (master) removed 28-Feb-2018 17:07:37.205 reloading zones succeeded 28-Feb-2018 17:07:37.244 zone_shutdown: zone example/IN: shutting down 28-Feb-2018 17:07:37.249 zone example/IN/internal: starting load 28-Feb-2018 17:07:37.251 zone example/IN/internal: number of nodes in database: 5 28-Feb-2018 17:07:37.251 zone example/IN/internal: journal rollforward completed successfully: no journal 28-Feb-2018 17:07:37.251 zone example/IN/internal: loaded; checking validity 28-Feb-2018 17:07:37.251 zone_settimer: zone example/IN/internal: enter 28-Feb-2018 17:07:37.251 zone example/IN/internal: loaded serial 2 28-Feb-2018 17:07:37.259 zone_timer: zone example/IN/internal: enter 28-Feb-2018 17:07:37.259 zone_maintenance: zone example/IN/internal: enter 28-Feb-2018 17:07:37.259 zone example/IN/internal: sending notifies (serial 2) 28-Feb-2018 17:07:37.259 zone_settimer: zone example/IN/internal: enter 28-Feb-2018 17:07:37.259 zone_settimer: zone example/IN/internal: settimer inactive 28-Feb-2018 17:07:37.263 zone example/IN/internal: sending notify to 10.53.0.3#5300 28-Feb-2018 17:07:37.307 zone example/IN/external: starting load 28-Feb-2018 17:07:37.308 zone example/IN/external: number of nodes in database: 4 28-Feb-2018 17:07:37.308 zone example/IN/external: journal rollforward completed successfully: no journal 28-Feb-2018 17:07:37.309 zone example/IN/external: loaded; checking validity 28-Feb-2018 17:07:37.309 zone_settimer: zone example/IN/external: enter 28-Feb-2018 17:07:37.309 zone example/IN/external: loaded serial 2 28-Feb-2018 17:07:37.313 zone example/IN/internal: notify response from 10.53.0.3#5300: NOERROR 28-Feb-2018 17:07:37.313 all zones loaded 28-Feb-2018 17:07:37.314 zone_timer: zone example/IN/external: enter 28-Feb-2018 17:07:37.314 zone_maintenance: zone example/IN/external: enter 28-Feb-2018 17:07:37.314 zone example/IN/external: sending notifies (serial 2) 28-Feb-2018 17:07:37.315 zone_settimer: zone example/IN/external: enter 28-Feb-2018 17:07:37.315 dns_zone_maintenance: zone example/IN/internal: enter 28-Feb-2018 17:07:37.315 zone_settimer: zone example/IN/external: settimer inactive 28-Feb-2018 17:07:37.315 zone_settimer: zone example/IN/internal: enter 28-Feb-2018 17:07:37.315 zone_settimer: zone example/IN/internal: settimer inactive 28-Feb-2018 17:07:37.325 dns_zone_maintenance: zone example/IN/external: enter 28-Feb-2018 17:07:37.325 zone_settimer: zone example/IN/external: enter 28-Feb-2018 17:07:37.326 zone_settimer: zone example/IN/external: settimer inactive 28-Feb-2018 17:07:37.391 client @0x7f93d08dfe10 10.53.0.3#56010 (example): view internal: transfer of 'example/IN': AXFR question section OK 28-Feb-2018 17:07:37.391 client @0x7f93d08dfe10 10.53.0.3#56010 (example): view internal: transfer of 'example/IN': AXFR authority section OK 28-Feb-2018 17:07:37.391 client @0x7f93d08dfe10 10.53.0.3#56010 (example): view internal: transfer of 'example/IN': AXFR started (serial 2) 28-Feb-2018 17:07:37.392 client @0x7f93d08dfe10 10.53.0.3#56010 (example): view internal: transfer of 'example/IN': sending TCP message of 227 bytes 28-Feb-2018 17:07:37.392 client @0x7f93d08dfe10 10.53.0.3#56010 (example): view internal: transfer of 'example/IN': AXFR ended ns3/named.run 28-Feb-2018 17:07:37.220 zone example/IN: not reusable: type mismatch 28-Feb-2018 17:07:37.286 zone example/IN: (master) removed 28-Feb-2018 17:07:37.287 zone_shutdown: zone example/IN: shutting down 28-Feb-2018 17:07:37.287 zone example/IN: notify from 10.53.0.2#56578: no serial 28-Feb-2018 17:07:37.287 queue_soa_query: zone example/IN: enter 28-Feb-2018 17:07:37.288 reloading zones succeeded 28-Feb-2018 17:07:37.288 soa_query: zone example/IN: enter 28-Feb-2018 17:07:37.388 refresh_callback: zone example/IN: enter 28-Feb-2018 17:07:37.388 refresh_callback: zone example/IN: serial: new 2, old not loaded 28-Feb-2018 17:07:37.389 queue_xfrin: zone example/IN: enter 28-Feb-2018 17:07:37.389 zone example/IN: Transfer started. 28-Feb-2018 17:07:37.389 zone example/IN: no database exists yet, requesting AXFR of initial version from 10.53.0.2#5300 28-Feb-2018 17:07:37.390 transfer of 'example/IN' from 10.53.0.2#5300: connected using 10.53.0.3#56010 28-Feb-2018 17:07:37.390 transfer of 'example/IN' from 10.53.0.2#5300: sent request data 28-Feb-2018 17:07:37.392 transfer of 'example/IN' from 10.53.0.2#5300: received 227 bytes 28-Feb-2018 17:07:37.393 transfer of 'example/IN' from 10.53.0.2#5300: got nonincremental response 28-Feb-2018 17:07:37.395 zone example/IN: replacing zone database 28-Feb-2018 17:07:37.395 zone example/IN: zone transfer finished: success 28-Feb-2018 17:07:37.395 zone example/IN: transferred serial 2 28-Feb-2018 17:07:37.395 zone_needdump: zone example/IN: enter 28-Feb-2018 17:07:37.395 zone_settimer: zone example/IN: enter 28-Feb-2018 17:07:37.395 zone_settimer: zone example/IN: enter 28-Feb-2018 17:07:37.395 transfer of 'example/IN' from 10.53.0.2#5300: Transfer status: success 28-Feb-2018 17:07:37.395 transfer of 'example/IN' from 10.53.0.2#5300: Transfer completed: 1 messages, 9 records, 227 bytes, 0.005 secs (45400 bytes/sec) 28-Feb-2018 17:07:37.395 zone_timer: zone example/IN: enter 28-Feb-2018 17:07:37.395 zone_maintenance: zone example/IN: enter 28-Feb-2018 17:07:37.402 all zones loaded 28-Feb-2018 17:07:37.405 dns_zone_maintenance: zone example/IN: enter 28-Feb-2018 17:07:37.405 zone_settimer: zone example/IN: enter 28-Feb-2018 17:07:37.405 zone_timer: zone example/IN: enter 28-Feb-2018 17:07:37.405 zone_maintenance: zone example/IN: enter 28-Feb-2018 17:07:37.405 zone example/IN: sending notifies (serial 2) 28-Feb-2018 17:07:37.405 zone_dump: zone example/IN: enter 28-Feb-2018 17:07:37.405 zone_settimer: zone example/IN: enter 28-Feb-2018 17:07:37.405 zone example/IN: sending notify to 10.53.0.2#5300 28-Feb-2018 17:07:37.405 zone_gotwritehandle: zone example/IN: enter 28-Feb-2018 17:07:37.406 dump_done: zone example/IN: enter 28-Feb-2018 17:07:37.406 zone_journal_compact: zone example/IN: target journal size 2240 28-Feb-2018 17:07:37.406 zone example/IN: dns_journal_compact: not found 28-Feb-2018 17:07:37.407 zone example/IN: notify response from 10.53.0.2#5300: NOERROR I:views:fetching a.example from ns2's 10.53.0.4, source address 10.53.0.4 I:views:fetching a.example from ns2's 10.53.0.2, source address 10.53.0.2 I:views:fetching a.example from ns3's 10.53.0.3, source address defaulted I:views:comparing ns3's initial a.example to one from reconfigured 10.53.0.2 I:views:comparing ns3's initial a.example to one from reconfigured 10.53.0.3 I:views:comparing ns2's initial a.example to one from reconfigured 10.53.0.4 I:views:comparing ns2's initial a.example to one from reconfigured 10.53.0.3 I:views:(should be different) I:views:updating cloned zone in internal view I:views:sleeping to allow update to take effect I:views:verifying update affected both views I:views:verifying forwarder in cloned zone works I:views:verifying inline zones work with views I:views:exit status: 0 R:views/:PASS E:views/:Wed 28 Feb 2018 17:07:44 AEDT