Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

rpz: url: with https: broken (regression in 1.13.1) #429

Closed
paukstis opened this issue Feb 19, 2021 · 10 comments
Closed

rpz: url: with https: broken (regression in 1.13.1) #429

paukstis opened this issue Feb 19, 2021 · 10 comments

Comments

@paukstis
Copy link

It seems https: transfers for rpz: url: do not work in 1.13.1 anymore, it was ok in 1.13.0, verbose log shows "debug: xfr stopped, connection timeout to ...", http: transfers are working fine.

@wcawijngaards
Copy link
Member

Is this on windows, or another system? For me authority zone transfer over https works fine and completes. The connection timeout is printed when there is in fact a timeout that happened, i.e. no events have happened for a while. Do you have more details, eg. if I wanted to reproduce this problem, with what settings would that happen?

@paukstis
Copy link
Author

This is on FreeBSD, running in dedicated jail for unbound, tested on FreeBSD 12.1 and 12.2, totally different hardware systems, same issue, https: transfers timeout. If I remove 1.13.1 package and reinstall 1.13.0 it works. Settings are mostly default, except RPZ is enabled by adding at the end of unbound.conf:

module-config: "respip validator iterator"

rpz:
  name: "energized_spark"
  url: https://block.energized.pro/spark/formats/rpz.txt

unbound.log with verbosity 10 shows following:

[1613738529] unbound[44063:0] info: respip operate: query block.energized.pro. A IN
[1613738529] unbound[44063:0] debug: mesh_run: respip module exit state is module_finished
[1613738529] unbound[44063:0] debug: auth host block.energized.pro lookup 136.243.241.83
[1613738529] unbound[44063:0] debug: comm point start listening 31 (-1 msec)
[1613738529] unbound[44063:0] debug: startlistening 31 mode w
[1613738529] unbound[44063:0] debug: auth zone energized_spark. transfer next HTTP fetch from 136.243.241.83 started
[1613738529] unbound[44063:0] info: mesh_run: end 0 recursion states (0 with reply, 0 detached), 0 waiting replies, 0 recursion replies sent, 0 replies dropped, 0 states jostled out
[1613738529] unbound[44063:0] debug: cache memory msg=68365 rrset=91654 infra=11120 val=69405
[1613738529] unbound[44063:0] debug: svcd callbacks end
[1613738529] unbound[44063:0] debug: serviced_delete
[1613738529] unbound[44063:0] debug: close of port 5284
[1613738529] unbound[44063:0] debug: comm_point_close of 32: event_del
[1613738529] unbound[44063:0] debug: close fd 32
[1613738529] unbound[44063:0] debug: comm point listen_for_rw 31 0
[1613738529] unbound[44063:0] debug: SSL connection ip4 136.243.241.83 port 443 (len 16)
[1613738529] unbound[44063:0] debug: comm point listen_for_rw 31 1
[1613738529] unbound[44063:0] debug: comm point stop listening 31
[1613738529] unbound[44063:0] debug: comm point start listening 31 (-1 msec)
[1613738529] unbound[44063:0] debug: startlistening 31 mode r
[1613738529] unbound[44063:0] debug: http header: HTTP/1.1 200 OK
[1613738529] unbound[44063:0] debug: http header: Server: nginx/1.14.0 (Ubuntu)
[1613738529] unbound[44063:0] debug: http header: Date: Fri, 19 Feb 2021 12:42:09 GMT
[1613738529] unbound[44063:0] debug: http header: Content-Type: text/plain
[1613738529] unbound[44063:0] debug: http header: Content-Length: 1133340
[1613738529] unbound[44063:0] debug: http header: Last-Modified: Fri, 19 Feb 2021 12:06:17 GMT
[1613738529] unbound[44063:0] debug: http header: Connection: keep-alive
[1613738529] unbound[44063:0] debug: http header: ETag: "602fa9b9-114b1c"
[1613738529] unbound[44063:0] debug: http header: Accept-Ranges: bytes
[1613738529] unbound[44063:0] debug: http header: 
[1613738539] unbound[44063:0] debug: xfr stopped, connection timeout to block.energized.pro
[1613738539] unbound[44063:0] debug: comm_point_close of 31: event_del
[1613738539] unbound[44063:0] debug: close fd 31
[1613738539] unbound[44063:0] debug: auth zone energized_spark. transfer failed, wait
[1613738539] unbound[44063:0] debug: auth zone energized_spark. timeout in 3 seconds

The FreeBSD jail has following packages:

expat-2.2.10                   XML 1.0 parser written in C
libevent-2.1.12                API for executing callback functions on events or timeouts
libnghttp2-1.43.0              HTTP/2.0 C Library
pkg-1.16.2                     Package manager
unbound-1.13.1                 Validating, recursive, and caching DNS resolver

@wcawijngaards
Copy link
Member

Thank you for the details! It turns out that when there was more data to be read in it would wait for more data, but then because the SSL connection did not provide more data yet, discard the existing data, and then wait for data to complete, but that would not happen any more. Also fixed it to read in, when possible, blocks of the encoding size of tls, for speed. It works for me with the fix.

jedisct1 added a commit to jedisct1/unbound that referenced this issue Feb 26, 2021
* nlnet/master: (103 commits)
  - Fix: Resolve interface names on control-interface too.
  - Fix for NLnetLabs#367: rc_ports don't have ub_sock; skip cleaning up.
  - Fix to allow rpz with wildcard that applies to all TLDs at once.
  Changelog note for NLnetLabs#365, NLnetLabs#367 and NLnetLabs#368. - Merge PR NLnetLabs#367 : DNSTAP log local address.  With code from PR NLnetLabs#365   and fixes NLnetLabs#368 : dnstap does not log the DNS message ID for   FORWARDER_QUERY.
  Fix comment item.
  Fix to use a simple pointer in the call of make_sock and make_sock_port.
  - spelling fix in header.
  - Fix unit test for added ulimit checks.
  - Fix function documentation.
  - On startup of unbound it checks if rlimits on memory size look   sufficient for the configured cache size, and logs warning if not.
  - ipsecmod: Better logging for detecting a cycle when attaching the   A/AAAA subquery.
  - Fix NLnetLabs#384: (1) A minor request to improve the log (2) A minor bug in   one log message.
  - Fix for zonemd, do not reject insecure result from trust anchor   validation step in dnssec chain of trust.
  - Fix for zonemd, that domain-insecure zones work without dnssec.
  Spelling fix.
  - Fix for zonemd, that nxdomain for the chain of trust is allowed   for island zones, it is treates as an insecure zone for verification.
  - Fix NLnetLabs#431: Squelch permission denied errors for tcp connect
  - rpz skip nsec3param records, and nicer log for unsupported actions.
  - Fix NLnetLabs#429: rpz: url: with https: broken (regression in 1.13.1).
  - Fix doxygen and pydoc warnings.
  ...
@paukstis
Copy link
Author

Any forecasted date for 1.13.2 ?

@wcawijngaards
Copy link
Member

There is no plan right now. We frequently make releases, a number of times per year.

@paukstis
Copy link
Author

Ok, thanks for reply, maybe a local cloned branch with this fix will do while waiting for next release.

@wcawijngaards
Copy link
Member

The code repository main branch is stable, and that could be as nice as a cloned branch. There is a snapshot in a tarball, of today's code version, in www.nlnetlabs.nl/~wouter/unbound-1.13.2_20210322.tar.gz .

@paukstis
Copy link
Author

Testing snapshot from 2021-03-22 master branch, and have now different issue with RPZ url: param. Transfers fail with larger zone (11 MB), here is one with verbose log:

module-config: "respip validator iterator"

rpz:
  name: "energized_blu"
  url: https://block.energized.pro/blu/formats/rpz.txt

unbound log:

[1616616829] unbound[3312:0] debug: ssl http read more skip to 0 + 16384
[1616616829] unbound[3312:0] debug: ssl http read more skip to 16384 + 16384
[1616616829] unbound[3312:0] debug: ssl http read more skip to 32768 + 16384
[1616616829] unbound[3312:0] debug: ssl http read more skip to 49152 + 16384
[1616616829] unbound[3312:0] debug: ssl http read more skip to 65536 + 16
[1616616829] unbound[3312:0] debug: auth zone transfer http callback
[1616616829] unbound[3312:0] debug: auth zone http queued up 65552 bytes
[1616616829] unbound[3312:0] debug: comm point start listening 30 (10000 msec)
[1616616829] unbound[3312:0] debug: startlistening 30 mode r
[1616616839] unbound[3312:0] debug: http took too long, dropped
[1616616839] unbound[3312:0] debug: comm_point_close of 30: event_del
[1616616839] unbound[3312:0] debug: close fd 30
[1616616839] unbound[3312:0] debug: auth zone transfer http callback
[1616616839] unbound[3312:0] debug: http stopped, connection lost to block.energized.pro
[1616616839] unbound[3312:0] debug: auth zone energized_blu. transfer failed, wait
[1616616839] unbound[3312:0] debug: auth zone energized_blu. timeout in 6 seconds

Test is running in the same jail as previously, default config, juste enabled RPZ zone.

@wcawijngaards
Copy link
Member

Thanks for that report. There is another error, and it is fixed in the commit.

The end of transfer did not work right because of the filesize accounting that was wrong. It is fixed in the code repository.

@paukstis
Copy link
Author

Looks good, thank you!

jedisct1 added a commit to jedisct1/unbound that referenced this issue Apr 22, 2021
* nlnet/master: (61 commits)
  - Fix that testcode dohclient has OpenSSL initialisation calls.
  - Further fix for NLnetLabs#468: detect SSL_CTX_set_alpn_protos for build with   OpenSSL 1.0.1.
  - Fix NLnetLabs#468: OpenSSL 1.0.1 can no longer build Unbound.
  Changelog note for NLnetLabs#466 - Merge NLnetLabs#466 from FGasper: Support OpenSSLs that lack   SSL_get0_alpn_selected.
  Support OpenSSLs that lack SSL_get0_alpn_selected.
  - Remove unused functions worker_handle_reply and   libworker_handle_reply.
  - Fix documentation comment for files previously residing in checkconf/.
  - Fix that nxdomain synthesis does not happen above the stub or   forward definition.
  - Fix (increase) verbosity level for iterator error log in   processQueryTargets().
  - Fix permission denied sendto log, squelch the log messages   unless high verbosity is set.
  - rebuild configure to set EXTRALINK to libunbound.la for NLnetLabs#460.
  - Fix for NLnetLabs#411: Depth protect for crash on deleted element timeout.
  - Fix to stop IPv6 PMTU discovery.
  Changelog note for NLnetLabs#460. - Merge NLnetLabs#460 from orbea: build: Link with the libtool archive.
  build: Link with the libtool archive.
  - Clean makedist.sh.
  - Fix stack-protector change to not override other CFLAGS options.
  - Disable the use of stack-protector for cross compiled 32-bit windows builds;   relates to NLnetLabs#444.
  - Fix NLnetLabs#429: Also fix end of transfer for http download of auth zones.
  - Fix that cachedb does not produce empty object files when disabled.
  ...
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants