`dns_passthru_*` does not work with DNS responses with 0 TTL

[alaviss]

Tuwunel 1.4.2

I tried the new dns_passthru_appservices introduced by #158, however this does not seem to work when tested against appservice ping endpoint.

The same result of the following test can be obtained with dns_passthru_domains.

Reproduction overview:

1. Configure an appservice with a return URL such that:
   • The resolved hostname have a DNS TTL of 0
   • The associated IP will change on service restart
2. Issue a GET /_matrix/client/v1/appservice/{id}/ping request using as_token
   • This request should succeed
3. Restart the appservice, it's IP should now change
4. Issue a GET /_matrix/client/v1/appservice/{id}/ping request using as_token
   • This request fails, and logs reveal that Tuwunel still stick to old DNS result. If dns_min_ttl is set to 0, the test will succeed.

Full reproduction test using podman: https://github.com/alaviss/tuwunel-dns-bug

Log summary:

• Appservice started with IP 10.89.0.3. Tuwunel managed to ping it.
• After appservice restart, it's IP is 10.89.0.5. It's verified that an another container within the same network can reach it using its DNS name.
• Tuwunel still attempts to reach the appservice using its old IP, thus timed out on all attempts.

Test run log

Creating temporary network
++ exec podman network create --internal
Created network podman1
Starting Tuwunel
++ exec podman run --detach --rm --security-opt=label=disable --log-driver=k8s-file --log-opt=path=/tmp/repro/containers.log --network=podman1 --volume ./tuwunel.toml:/tuwunel.toml:ro --env=TUWUNEL_CONFIG=/tuwunel.toml --name=test-tuwunel ghcr.io/matrix-construct/tuwunel:v1.4.2
Started Tuwunel as 62625bde195c7fca6ced21e22c4616b47439aa034102ef8cec1df6d79f778e1a
Starting appservice ping receiver
++ exec podman run --detach --rm --security-opt=label=disable --log-driver=k8s-file --log-opt=path=/tmp/repro/containers.log --network=podman1 --volume ./index.mjs:/app/index.mjs:ro --name=test-appservice registry.access.redhat.com/ubi10/nodejs-22-minimal:latest node /app/index.mjs
Started ping receiver as 42d95b2b118e2c30deee879a72667eb71499b3bbd750e193fd7c65f5305abaa2
Starting tool container
++ exec podman run --detach --rm --security-opt=label=disable --log-driver=k8s-file --log-opt=path=/tmp/repro/containers.log --network=podman1 --init registry.access.redhat.com/ubi10:latest sh -c 'sleep infinity & wait'
Started tool container as 51f980c8bcc79a1812d4bcd5125094fd99df189fa3ed1fd2b2adc17b09d90b51
Check server version
+ exec podman exec -i 51f980c8bcc79a1812d4bcd5125094fd99df189fa3ed1fd2b2adc17b09d90b51 curl --retry 3 --retry-delay 3 --retry-all-errors --fail-with-body http://test-tuwunel:8008/_matrix/federation/v1/version
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100    96    0    96    0     0  20801      0 --:--:-- --:--:-- --:--:-- 24000
{"server":{"name":"Tuwunel","version":"1.4.2","compiler":"rustc 1.88.0 (6b00bc388 2025-06-23)"}}
Manually ping appservice
+ exec podman exec -i 51f980c8bcc79a1812d4bcd5125094fd99df189fa3ed1fd2b2adc17b09d90b51 curl -v --retry 3 --retry-delay 3 --retry-all-errors --fail-with-body http://test-appservice:8000/_matrix/app/v1/ping
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0* Host test-appservice:8000 was resolved.
* IPv6: (none)
* IPv4: 10.89.0.3
*   Trying 10.89.0.3:8000...
* Connected to test-appservice (10.89.0.3) port 8000
> GET /_matrix/app/v1/ping HTTP/1.1
> Host: test-appservice:8000
> User-Agent: curl/8.9.1
> Accept: */*
>
* Request completely sent off
< HTTP/1.1 200 OK
< Content-Type: application/json
< Date: Sun, 21 Sep 2025 03:11:40 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
< Transfer-Encoding: chunked
<
{ [12 bytes data]
100     2    0     2    0     0    300      0 --:--:-- --:--:-- --:--:--   333
* Connection #0 to host test-appservice left intact
{}
Ping appservice via Tuwunel
+ exec podman exec -i 51f980c8bcc79a1812d4bcd5125094fd99df189fa3ed1fd2b2adc17b09d90b51 curl --fail-with-body '-d{}' -H 'Authorization: Bearer test_token_as' http://test-tuwunel:8008/_matrix/client/v1/appservice/test/ping
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100    19    0    17  100     2   3424    402 --:--:-- --:--:-- --:--:--  4750
{"duration_ms":2}
Restarting appservice receiver
+ exec podman stop 42d95b2b118e2c30deee879a72667eb71499b3bbd750e193fd7c65f5305abaa2
42d95b2b118e2c30deee879a72667eb71499b3bbd750e193fd7c65f5305abaa2
++ exec podman run --detach --rm --security-opt=label=disable --log-driver=k8s-file --log-opt=path=/tmp/repro/containers.log --network=podman1 --volume ./index.mjs:/app/index.mjs:ro --name=test-appservice registry.access.redhat.com/ubi10/nodejs-22-minimal:latest node /app/index.mjs
Started ping receiver as 9965061e2be6e884ca02e795143356ee05df81664d40551547767f8c861fd539
Manually ping appservice (again)
+ exec podman exec -i 51f980c8bcc79a1812d4bcd5125094fd99df189fa3ed1fd2b2adc17b09d90b51 curl -v --retry 3 --retry-delay 3 --retry-all-errors --fail-with-body http://test-appservice:8000/_matrix/app/v1/ping
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0* Host test-appservice:8000 was resolved.
* IPv6: (none)
* IPv4: 10.89.0.5
*   Trying 10.89.0.5:8000...
* connect to 10.89.0.5 port 8000 from 10.89.0.4 port 39348 failed: Connection refused
* Failed to connect to test-appservice port 8000 after 1 ms: Could not connect to server
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
* closing connection #0
curl: (7) Failed to connect to test-appservice port 8000 after 1 ms: Could not connect to server
Warning: Problem (retrying all errors). Will retry in 3 seconds. 3 retries
Warning: left.
* Hostname test-appservice was found in DNS cache
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0*   Trying 10.89.0.5:8000...
* Connected to test-appservice (10.89.0.5) port 8000
> GET /_matrix/app/v1/ping HTTP/1.1
> Host: test-appservice:8000
> User-Agent: curl/8.9.1
> Accept: */*
>
* Request completely sent off
< HTTP/1.1 200 OK
< Content-Type: application/json
< Date: Sun, 21 Sep 2025 03:11:44 GMT
< Connection: keep-alive
< Keep-Alive: timeout=5
< Transfer-Encoding: chunked
<
{ [12 bytes data]
100     2    0     2    0     0    283      0 --:--:-- --:--:-- --:--:--   285
* Connection #1 to host test-appservice left intact
{}
Ping appservice via Tuwunel (again)
+ exec podman exec -i 51f980c8bcc79a1812d4bcd5125094fd99df189fa3ed1fd2b2adc17b09d90b51 curl --retry 3 --retry-delay 3 --retry-all-errors --fail-with-body '-d{}' -H 'Authorization: Bearer test_token_as' http://test-tuwunel:8008/_matrix/client/v1/appservice/test/ping
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   157    0   155    0     2     30      0 --:--:--  0:00:05 --:--:--    38
curl: (22) The requested URL returned error: 500
{"errcode":"M_UNKNOWN","error":"Request error: error sending request for url (http://test-appservice:8000/_matrix/app/v1/ping?access_token=test_token_hs)"}Warning: Problem : HTTP error. Will retry in 3 seconds. 3 retries left.
100   157    0   155    0     2     30      0 --:--:--  0:00:05 --:--:--    38
curl: (22) The requested URL returned error: 500
{"errcode":"M_UNKNOWN","error":"Request error: error sending request for url (http://test-appservice:8000/_matrix/app/v1/ping?access_token=test_token_hs)"}Warning: Problem : HTTP error. Will retry in 3 seconds. 2 retries left.
100   157    0   155    0     2     30      0 --:--:--  0:00:05 --:--:--    38
curl: (22) The requested URL returned error: 500
{"errcode":"M_UNKNOWN","error":"Request error: error sending request for url (http://test-appservice:8000/_matrix/app/v1/ping?access_token=test_token_hs)"}Warning: Problem : HTTP error. Will retry in 3 seconds. 1 retries left.
100   157    0   155    0     2     30      0 --:--:--  0:00:05 --:--:--    38
curl: (22) The requested URL returned error: 5{"errcode":"M_UNKNOWN","error":"Request error: error sending request for url (http://test-appservice:8000/_matrix/app/v1/ping?access_token=test_token_hs)"}00
Stopping spawned containers
51f980c8bcc79a1812d4bcd5125094fd99df189fa3ed1fd2b2adc17b09d90b51
9965061e2be6e884ca02e795143356ee05df81664d40551547767f8c861fd539
62625bde195c7fca6ced21e22c4616b47439aa034102ef8cec1df6d79f778e1a
Removing network podman1
podman1

Tuwunel and receiver log

2025-09-20T22:11:40.046362449-05:00 stdout F 2025-09-21T03:11:40.046310Z  INFO tuwunel::server: 1.4.2 server_name=localhost database_path="/tmp/tuwunel" log_levels=info
2025-09-20T22:11:40.110935389-05:00 stdout F 2025-09-21T03:11:40.110485Z  INFO main:start:open: tuwunel_database::engine::open: Opened database. columns=91 sequence=0 time=49.424681ms
2025-09-20T22:11:40.119129894-05:00 stdout F 2025-09-21T03:11:40.119100Z  WARN main:start: tuwunel_service::migrations: Created new RocksDB database with version 17
2025-09-20T22:11:40.125439184-05:00 stdout F 2025-09-21T03:11:40.125399Z  INFO tuwunel_router::serve::plain: Listening on [0.0.0.0:8008]
2025-09-20T22:11:40.379931135-05:00 stdout F test-appservice: Started receiver on port 8000
2025-09-20T22:11:40.645950856-05:00 stdout F 2025-09-21T03:11:40.645917Z  WARN admin:command: tuwunel_admin::user::commands: Granting @admin:localhost admin privileges as the first user
2025-09-20T22:11:40.646659592-05:00 stdout F │level│ span  │             message              │
2025-09-20T22:11:40.646659592-05:00 stdout F ├─────┼───────┼──────────────────────────────────┤
2025-09-20T22:11:40.646659592-05:00 stdout F │ WARN│command│Granting @admin:localhost admin   │
2025-09-20T22:11:40.646665592-05:00 stdout F │     │       │privileges as the first user      │
2025-09-20T22:11:40.646665592-05:00 stdout F
2025-09-20T22:11:40.646665592-05:00 stdout F Created user with user_id: @admin:localhost and
2025-09-20T22:11:40.646665592-05:00 stdout F password: QVmrsoCgvBGm3s4akuc1duXXX
2025-09-20T22:11:40.709407958-05:00 stdout F test-appservice: GET /_matrix/app/v1/ping
2025-09-20T22:11:40.933738850-05:00 stdout F test-appservice: POST /_matrix/app/v1/ping?access_token=test_token_hs
2025-09-20T22:11:41.125794617-05:00 stdout F test-appservice: Received SIGTERM. Terminating
2025-09-20T22:11:41.659899077-05:00 stdout F test-appservice: Started receiver on port 8000
2025-09-20T22:11:44.599348321-05:00 stdout F test-appservice: GET /_matrix/app/v1/ping
2025-09-20T22:11:49.848960919-05:00 stdout F 2025-09-21T03:11:49.848918Z  WARN tuwunel_service::sending::appservice: Could not send request to appservice "test" at http://test-appservice:8000: reqwest::Error { kind: Request, url: "http://test-appservice:8000/_matrix/app/v1/ping?access_token=test_token_hs", source: hyper_util::client::legacy::Error(Connect, ConnectError("tcp connect error", 10.89.0.3:8000, Custom { kind: TimedOut, error: Elapsed(()) })) }
2025-09-20T22:11:49.848994019-05:00 stdout F   2025-09-21T03:11:49.848980Z ERROR tuwunel_router::request: 500 Internal Server Error, method: POST, uri: /_matrix/client/v1/appservice/test/ping
2025-09-20T22:11:49.848994019-05:00 stdout F     at src/router/request.rs:115 on tuwunel:worker ThreadId(6)
2025-09-20T22:11:49.848994019-05:00 stdout F
2025-09-20T22:11:49.849006669-05:00 stdout F   2025-09-21T03:11:49.848997Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 5001 ms
2025-09-20T22:11:49.849006669-05:00 stdout F     at /opt/rust/cargo/debian/x86_64-linux-gnu/registry/src/index.crates.io-1949cf8c6b5b557f/tower-http-0.6.6/src/trace/on_failure.rs:93 on tuwunel:worker ThreadId(6)
2025-09-20T22:11:49.849006669-05:00 stdout F
2025-09-20T22:11:57.851742739-05:00 stdout F 2025-09-21T03:11:57.851702Z  WARN tuwunel_service::sending::appservice: Could not send request to appservice "test" at http://test-appservice:8000: reqwest::Error { kind: Request, url: "http://test-appservice:8000/_matrix/app/v1/ping?access_token=test_token_hs", source: hyper_util::client::legacy::Error(Connect, ConnectError("tcp connect error", 10.89.0.3:8000, Custom { kind: TimedOut, error: Elapsed(()) })) }
2025-09-20T22:11:57.851793209-05:00 stdout F   2025-09-21T03:11:57.851775Z ERROR tuwunel_router::request: 500 Internal Server Error, method: POST, uri: /_matrix/client/v1/appservice/test/ping
2025-09-20T22:11:57.851793209-05:00 stdout F     at src/router/request.rs:115 on tuwunel:worker ThreadId(6)
2025-09-20T22:11:57.851793209-05:00 stdout F
2025-09-20T22:11:57.851811479-05:00 stdout F   2025-09-21T03:11:57.851798Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 5000 ms
2025-09-20T22:11:57.851811479-05:00 stdout F     at /opt/rust/cargo/debian/x86_64-linux-gnu/registry/src/index.crates.io-1949cf8c6b5b557f/tower-http-0.6.6/src/trace/on_failure.rs:93 on tuwunel:worker ThreadId(6)
2025-09-20T22:11:57.851811479-05:00 stdout F
2025-09-20T22:12:05.855974119-05:00 stdout F 2025-09-21T03:12:05.855938Z  WARN tuwunel_service::sending::appservice: Could not send request to appservice "test" at http://test-appservice:8000: reqwest::Error { kind: Request, url: "http://test-appservice:8000/_matrix/app/v1/ping?access_token=test_token_hs", source: hyper_util::client::legacy::Error(Connect, ConnectError("tcp connect error", 10.89.0.3:8000, Custom { kind: TimedOut, error: Elapsed(()) })) }
2025-09-20T22:12:05.856018959-05:00 stdout F   2025-09-21T03:12:05.856003Z ERROR tuwunel_router::request: 500 Internal Server Error, method: POST, uri: /_matrix/client/v1/appservice/test/ping
2025-09-20T22:12:05.856018959-05:00 stdout F     at src/router/request.rs:115 on tuwunel:worker ThreadId(6)
2025-09-20T22:12:05.856018959-05:00 stdout F
2025-09-20T22:12:05.856034729-05:00 stdout F   2025-09-21T03:12:05.856023Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 5001 ms
2025-09-20T22:12:05.856034729-05:00 stdout F     at /opt/rust/cargo/debian/x86_64-linux-gnu/registry/src/index.crates.io-1949cf8c6b5b557f/tower-http-0.6.6/src/trace/on_failure.rs:93 on tuwunel:worker ThreadId(6)
2025-09-20T22:12:05.856034729-05:00 stdout F
2025-09-20T22:12:13.861030967-05:00 stdout F 2025-09-21T03:12:13.860994Z  WARN tuwunel_service::sending::appservice: Could not send request to appservice "test" at http://test-appservice:8000: reqwest::Error { kind: Request, url: "http://test-appservice:8000/_matrix/app/v1/ping?access_token=test_token_hs", source: hyper_util::client::legacy::Error(Connect, ConnectError("tcp connect error", 10.89.0.3:8000, Custom { kind: TimedOut, error: Elapsed(()) })) }
2025-09-20T22:12:13.861076437-05:00 stdout F   2025-09-21T03:12:13.861060Z ERROR tuwunel_router::request: 500 Internal Server Error, method: POST, uri: /_matrix/client/v1/appservice/test/ping
2025-09-20T22:12:13.861076437-05:00 stdout F     at src/router/request.rs:115 on tuwunel:worker ThreadId(6)
2025-09-20T22:12:13.861076437-05:00 stdout F
2025-09-20T22:12:13.861092527-05:00 stdout F   2025-09-21T03:12:13.861079Z ERROR tower_http::trace::on_failure: response failed, classification: Status code: 500 Internal Server Error, latency: 5001 ms
2025-09-20T22:12:13.861092527-05:00 stdout F     at /opt/rust/cargo/debian/x86_64-linux-gnu/registry/src/index.crates.io-1949cf8c6b5b557f/tower-http-0.6.6/src/trace/on_failure.rs:93 on tuwunel:worker ThreadId(6)
2025-09-20T22:12:13.861092527-05:00 stdout F
2025-09-20T22:12:13.990086286-05:00 stdout F test-appservice: Received SIGTERM. Terminating
2025-09-20T22:12:14.068616747-05:00 stdout F 2025-09-21T03:12:14.068571Z  WARN signal: tuwunel::signal: Received SIGTERM
2025-09-20T22:12:14.069015060-05:00 stdout F 2025-09-21T03:12:14.068994Z  INFO main:stop: tuwunel_service::services: Shutting down services...
2025-09-20T22:12:14.069370223-05:00 stdout F 2025-09-21T03:12:14.069360Z  INFO main:stop: tuwunel_router::run: Shutdown complete.

[jevolk]

Are you aware of what the effective TTL is? The configuration for minimum-ttl of the new resolver is set to the hickory-dns default. I have confirmed the new resolver is in use for matching domains. This would mean hickory-dns is still imposing its own minimum internally which would be disappointing. It was probably a mistake to not simply set this to hard 0 but I went with just using their defaults. I'm currently going through their code right now to see what I can find.

What effective behavior are you eventually seeing?

[jevolk]

Okay I think I found the problem here. Looks like I rushed this one and the TTL is overwritten. Sorry about that 😭

[jevolk]

It should be safe to set the dns_min_ttl to 0 until the fix is applied in the next release. The federation resolver still passes through the persistent caches and then only uses the TTL provided by the remote server after those expire. Only a subset of remote servers provide low TTL's which the minimum pads against.

[alaviss]

Thanks for the quick response 🚀