starred/hickory-dns

Fork 0

mirror of https://github.com/hickory-dns/hickory-dns.git synced 2026-04-25 19:25:56 +03:00

[GH-ISSUE #3064] Tracing log level for DoH connection close #1122

New issue

Closed

opened 2026-03-16 01:40:31 +03:00 by kerem · 4 comments

kerem commented

2026-03-16 01:40:31 +03:00

Owner

Originally created by @jmwample on GitHub (Jun 17, 2025).
Original GitHub issue: https://github.com/hickory-dns/hickory-dns/issues/3064

Is your feature request related to a problem? Please describe.
We use the DoH and DoT features of the hickory dialer as well as the tracing and tracing-subscriber tooling and continuously see logs relating to h2 connection failure in the following format:

2025-06-17T21:03:08.846705Z  WARN hickory_proto::h2::h2_client_stream: h2 connection failed: unexpected end of file
2025-06-17T21:03:08.934461Z  WARN hickory_proto::h2::h2_client_stream: h2 connection failed: unexpected end of file

These log lines have ended up as red herrings for bug hunts related to other things. In debug logs for the same event:

2025-06-17T21:03:08.846373Z DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(3), debug_data: b"idle timeout" }
2025-06-17T21:03:08.846479Z DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(3), debug_data: b"idle timeout" }
2025-06-17T21:03:08.846536Z DEBUG Connection{peer=Client}: h2::proto::connection: Connection::poll; IO error error=UnexpectedEof
2025-06-17T21:03:08.846705Z  WARN hickory_proto::h2::h2_client_stream: h2 connection failed: unexpected end of file
2025-06-17T21:03:08.934250Z DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(3), debug_data: b"idle timeout" }
2025-06-17T21:03:08.934321Z DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(3), debug_data: b"idle timeout" }
2025-06-17T21:03:08.934354Z DEBUG Connection{peer=Client}: h2::proto::connection: Connection::poll; IO error error=UnexpectedEof                        
2025-06-17T21:03:08.934461Z  WARN hickory_proto::h2::h2_client_stream: h2 connection failed: unexpected end of file

What I believe is happening is that the DNS-over-HTTPS client uses H2 and keeps a tls connection open, but cloud providers don't like when people keep connections open indefinitely because it means you are keeping state in their servers. So after some time they close the connection -- apparently with the go away message. The DoH client logs a warning about this even though it is a perfectly valid way for the server side to operate, and the DNS client just opens a new connection when it needs to do a subsequent resolution.

Describe the solution you'd like
Consider reducing the h2 connection EoF logging from warning to debug or consider handling the go away message without logging a warning (i.e. other errors there would still log at warning level).

This is the protocol operating as intended, not an unexpected error. I believe that the line that triggers this log is github.com/hickory-dns/hickory-dns@1476c0616e/crates/proto/src/h2/h2_client_stream.rs (L537)

Describe alternatives you've considered
We have considered simply changing the logging verbosity for the hickory_crate crate such that the log level is artificially dampened in the instantiated subscriber, but this exception has to be independently added for every tool we build that uses the hickory resolver and tracing.

Additionally the issue is often DNS and we want the detailed debugging without the artificially dampened log level or without creating tooling centered around modifying the log level of this specific library when debugging.

Thank you!

Originally created by @jmwample on GitHub (Jun 17, 2025). Original GitHub issue: https://github.com/hickory-dns/hickory-dns/issues/3064 **Is your feature request related to a problem? Please describe.** We use the DoH and DoT features of the hickory dialer as well as the `tracing` and `tracing-subscriber` tooling and continuously see logs relating to h2 connection failure in the following format: ```log 2025-06-17T21:03:08.846705Z WARN hickory_proto::h2::h2_client_stream: h2 connection failed: unexpected end of file 2025-06-17T21:03:08.934461Z WARN hickory_proto::h2::h2_client_stream: h2 connection failed: unexpected end of file ``` These log lines have ended up as red herrings for bug hunts related to other things. In debug logs for the same event: ``` 2025-06-17T21:03:08.846373Z DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(3), debug_data: b"idle timeout" } 2025-06-17T21:03:08.846479Z DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(3), debug_data: b"idle timeout" } 2025-06-17T21:03:08.846536Z DEBUG Connection{peer=Client}: h2::proto::connection: Connection::poll; IO error error=UnexpectedEof 2025-06-17T21:03:08.846705Z WARN hickory_proto::h2::h2_client_stream: h2 connection failed: unexpected end of file 2025-06-17T21:03:08.934250Z DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(3), debug_data: b"idle timeout" } 2025-06-17T21:03:08.934321Z DEBUG Connection{peer=Client}: h2::codec::framed_read: received frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(3), debug_data: b"idle timeout" } 2025-06-17T21:03:08.934354Z DEBUG Connection{peer=Client}: h2::proto::connection: Connection::poll; IO error error=UnexpectedEof 2025-06-17T21:03:08.934461Z WARN hickory_proto::h2::h2_client_stream: h2 connection failed: unexpected end of file ``` What I believe is happening is that the DNS-over-HTTPS client uses H2 and keeps a tls connection open, but cloud providers don't like when people keep connections open indefinitely because it means you are keeping state in their servers. So after some time they close the connection -- apparently with the `go away` message. The DoH client logs a warning about this even though it is a perfectly valid way for the server side to operate, and the DNS client just opens a new connection when it needs to do a subsequent resolution. **Describe the solution you'd like** Consider reducing the h2 connection EoF logging from warning to debug or consider handling the go away message without logging a warning (i.e. other errors there would still log at warning level). This is the protocol operating as intended, not an unexpected error. I believe that the line that triggers this log is https://github.com/hickory-dns/hickory-dns/blob/1476c0616e4653a58351abcf22ee512fad43fa6b/crates/proto/src/h2/h2_client_stream.rs#L537 **Describe alternatives you've considered** We have considered simply changing the logging verbosity for the `hickory_crate` crate such that the log level is artificially dampened in the instantiated subscriber, but this exception has to be independently added for every tool we build that uses the hickory resolver and tracing. Additionally the issue is often DNS and we want the detailed debugging without the artificially dampened log level or without creating tooling centered around modifying the log level of this specific library when debugging. Thank you!

kerem closed this issue

2026-03-16 01:40:36 +03:00

kerem commented

2026-03-16 01:40:42 +03:00

Author

Owner

@djc commented on GitHub (Jun 17, 2025):

Sounds fair, want to submit a PR?

@djc commented on GitHub (Jun 17, 2025): Sounds fair, want to submit a PR?

kerem commented

2026-03-16 01:40:47 +03:00

Author

Owner

@jmwample commented on GitHub (Jun 17, 2025):

I would be happy to

@jmwample commented on GitHub (Jun 17, 2025): I would be happy to

kerem commented

2026-03-16 01:40:52 +03:00

Author

Owner

@jmwample commented on GitHub (Jun 30, 2025):

Update: This issue should be solved once a release is available including https://github.com/hyperium/h2/pull/847

Thanks for your help & attention on this

@jmwample commented on GitHub (Jun 30, 2025): Update: This issue should be solved once a release is available including https://github.com/hyperium/h2/pull/847 Thanks for your help & attention on this

kerem commented

2026-03-16 01:40:57 +03:00

Author

Owner

@djc commented on GitHub (Jun 30, 2025):

Update: This issue should be solved once a release is available including https://github.com/hyperium/h2/pull/847

Thanks for your help & attention on this

Thank you for the upstream fix!

@djc commented on GitHub (Jun 30, 2025): > Update: This issue should be solved once a release is available including https://github.com/hyperium/h2/pull/847 > > Thanks for your help & attention on this Thank you for the upstream fix!

kerem referenced this issue

2026-03-16 04:20:29 +03:00

[PR #1122] [CLOSED] Bump async-std from 1.5.0 to 1.6.0 #1989