make test 1.16.1 fails on Solaris 10

Wouter Wijngaards wouter at nlnetlabs.nl
Tue Jul 12 06:43:57 UTC 2022 

Hi Ihsan,

This issue is fixed with commit
https://github.com/NLnetLabs/unbound/commit/769639823108bb6837a1c43897fa86e9460d5f2a
that fixes the EDE error printout to logs.

It is the log printout during the test that fails, the commit fixes it.
Thanks for reporting it!

Best regards, Wouter

On 11/07/22 19:55, İhsan Doğan via Unbound-users wrote:
> Hi,
> 
> I was updating the Solaris 10 package to 1.16.1 and noticed, that make test fails. This was running fine with 1.16.0.
> 
> 
> 
> 
> Regards
> 
> Ihsan
> 
> 
> [1657561424] unbound[22642:0] debug: query took 0.000000 sec
> [1657561424] unbound[22642:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
> [1657561424] unbound[22642:0] info: average recursion processing time 0.000000 sec
> [1657561424] unbound[22642:0] info: histogram of recursion processing times
> [1657561424] unbound[22642:0] info: [25%]=0 median[50%]=0 [75%]=0
> [1657561424] unbound[22642:0] info: lower(secs) upper(secs) recursions
> [1657561424] unbound[22642:0] info:    0.000000    0.000001 1
> [1657561424] unbound[22642:0] debug: cache memory msg=131649 rrset=131976 infra=13376 val=131588
> [1657561424] unbound[22642:0] info: testbound: end of event stage
> [1657561424] unbound[22642:0] debug: comparepkt: 
> [1657561424] unbound[22642:0] debug: match!
> 
> [1657561424] unbound[22642:0] info: testbound matched event entry from line 69
> [1657561424] unbound[22642:0] info: testbound: do STEP 10 CHECK_ANSWER
> [1657561424] unbound[22642:0] info: testbound: end of event stage
> [1657561424] unbound[22642:0] info: testbound: do STEP 11 TIME_PASSES
> [1657561424] unbound[22642:0] info: elapsed 3600.000000  now 3600.000000
> [1657561424] unbound[22642:0] info: testbound: end of event stage
> [1657561424] unbound[22642:0] info: testbound: do STEP 30 QUERY
> [1657561424] unbound[22642:0] info: testbound: incoming QUERY
> [1657561424] unbound[22642:0] info: query pkt;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
> ;; flags: rd ; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 1 
> ;; QUESTION SECTION:
> example.com.    IN      A
> 
> ;; ANSWER SECTION:
> 
> ;; AUTHORITY SECTION:
> 
> ;; ADDITIONAL SECTION:
> ; EDNS: version: 0; flags: do ; udp: 1232
> ;; MSG SIZE  rcvd: 40
> 
> [1657561424] unbound[22642:0] debug: answer from the cache failed
> [1657561424] unbound[22642:0] debug: udp request from ip4 127.0.0.1 port 53 (len 16)
> [1657561424] unbound[22642:0] info: fake timer set 0.001000
> [1657561424] unbound[22642:0] debug: mesh_run: start
> [1657561424] unbound[22642:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new
> [1657561424] unbound[22642:0] info: validator operate: query example.com. A IN
> [1657561424] unbound[22642:0] debug: validator: pass to next module
> [1657561424] unbound[22642:0] debug: mesh_run: validator module exit state is module_wait_module
> [1657561424] unbound[22642:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
> [1657561424] unbound[22642:0] debug: process_request: new external request event
> [1657561424] unbound[22642:0] debug: iter_handle processing q with state INIT REQUEST STATE
> [1657561424] unbound[22642:0] info: resolving example.com. A IN
> [1657561424] unbound[22642:0] debug: request has dependency depth of 0
> [1657561424] unbound[22642:0] debug: cache delegation returns delegpt
> [1657561424] unbound[22642:0] info: DelegationPoint<example.com.>: 1 names (1 missing), 1 addrs (0 result, 1 avail) cacheNS
> [1657561424] unbound[22642:0] info:   ns.example.com.  A
> [1657561424] unbound[22642:0] debug:    ip4 1.2.3.4 port 53 (len 16)
> [1657561424] unbound[22642:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 2)
> [1657561424] unbound[22642:0] info: resolving (init part 2):  example.com. A IN
> [1657561424] unbound[22642:0] info: use stub example.com. NS IN
> [1657561424] unbound[22642:0] debug: iter_handle processing q with state INIT REQUEST STATE (stage 3)
> [1657561424] unbound[22642:0] info: resolving (init part 3):  example.com. A IN
> [1657561424] unbound[22642:0] debug: iter_handle processing q with state QUERY TARGETS STATE
> [1657561424] unbound[22642:0] info: processQueryTargets: example.com. A IN
> [1657561424] unbound[22642:0] debug: processQueryTargets: targetqueries 0, currentqueries 0 sentcount 0
> [1657561424] unbound[22642:0] info: DelegationPoint<example.com.>: 0 names (0 missing), 1 addrs (0 result, 1 avail) parentNS
> [1657561424] unbound[22642:0] debug:    ip4 1.2.3.4 port 53 (len 16)
> [1657561424] unbound[22642:0] debug: attempt to get extra 3 targets
> [1657561424] unbound[22642:0] debug: rpz: iterator module callback: have_rpz=0
> [1657561424] unbound[22642:0] debug: selrtt 376
> [1657561424] unbound[22642:0] info: sending query: example.com. A IN
> [1657561424] unbound[22642:0] debug: sending to target: <example.com.> 1.2.3.4#53
> [1657561424] unbound[22642:0] debug: dnssec status: not expected
> [1657561424] unbound[22642:0] info: pending serviced query example.com. A IN
> [1657561424] unbound[22642:0] notice: pending serviced query zone example.com. flags DO
> [1657561424] unbound[22642:0] info: testbound: created fake pending
> [1657561424] unbound[22642:0] debug: mesh_run: iterator module exit state is module_wait_reply
> [1657561424] unbound[22642:0] info: mesh_run: end 1 recursion states (1 with reply, 0 detached), 1 waiting replies, 1 recursion replies sent, 0 replies dropped, 0 states jostled out
> [1657561424] unbound[22642:0] info: average recursion processing time 0.000000 sec
> [1657561424] unbound[22642:0] info: histogram of recursion processing times
> [1657561424] unbound[22642:0] info: [25%]=0 median[50%]=0 [75%]=0
> [1657561424] unbound[22642:0] info: lower(secs) upper(secs) recursions
> [1657561424] unbound[22642:0] info:    0.000000    0.000001 1
> [1657561424] unbound[22642:0] info: 0RDd mod1 rep example.com. A IN
> [1657561424] unbound[22642:0] debug: cache memory msg=131649 rrset=131976 infra=13376 val=131588
> [1657561424] unbound[22642:0] info: testbound: end of event stage
> [1657561424] unbound[22642:0] debug: comparepkt: 
> [1657561424] unbound[22642:0] debug: bad qtype 1 2
> 
> [1657561424] unbound[22642:0] info: testbound: do STEP 31 TIME_PASSES
> [1657561424] unbound[22642:0] info: elapsed 1.000000  now 3601.000000
> [1657561424] unbound[22642:0] info: fake_timer callback
> [1657561424] unbound[22642:0] debug: Serve expired: Trying to reply with expired data
> [1657561424] unbound[22642:0] info: Serve expired lookup ;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 0
> ;; flags: qr ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 1, ADDITIONAL: 1 
> ;; QUESTION SECTION:
> example.com.    IN      A
> 
> ;; ANSWER SECTION:
> example.com.    123     IN      A       5.6.7.8
> 
> ;; AUTHORITY SECTION:
> example.com.    123     IN      NS      ns.example.com.
> 
> ;; ADDITIONAL SECTION:
> ns.example.com. 123     IN      A       1.2.3.4
> ;; MSG SIZE  rcvd: 78 
> ./testdata/serve_expired_client_timeout.rpl  failed
> gmake: *** [Makefile:347: test] Error 1
>

More information about the Unbound-users mailing list