getting 30 secs delay while getting metrics

[rambabubolla]

I have deployed it on ubuntu both unbound and unbound-telemetry on same node.
Any one facing this 30sec dealy while getting unbound stats
$time wget 127.0.0.1:9167/metrics
--2021-03-18 11:30:50-- http://127.0.0.1:9167/metrics
Connecting to 127.0.0.1:9167... connected.
HTTP request sent, awaiting response... 200 OK
Length: 6092 (5.9K) [text/plain]
Saving to: ‘metrics’

metrics 100%[============================================================================>] 5.95K --.-KB/s in 0s

2021-03-18 11:31:20 (348 MB/s) - ‘metrics’ saved [6092/6092]

real 0m30.037s
user 0m0.006s
sys 0m0.000s

[svartalf]

This is quite odd, @rambabubolla.

What connection type are you using, TCP, UDS or shared memory?
Is unbound installed on the same machine?

It also might be a network issue, maybe worth to check it too?

[rambabubolla]

Still same issue with the branch close-remote-control-socket
please refer below telemetry logs and unbound logs

TRACE [mio::poll] deregistering handle with poller
TRACE [mio::poll] registering with poller
TRACE [hyper::proto::h1::conn] Conn::read_head
TRACE [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Busy }
TRACE [hyper::proto::h1::conn] Conn::read_head
DEBUG [hyper::proto::h1::io] read 148 bytes
TRACE [hyper::proto::h1::role] Request.parse([Header; 100], [u8; 148])
TRACE [hyper::proto::h1::role] Request.parse Complete(148)
DEBUG [hyper::proto::h1::io] parsed 5 headers
DEBUG [hyper::proto::h1::conn] incoming body is empty
TRACE [mio::poll] registering with poller
TRACE [hyper::proto::h1::conn] flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy }
TRACE [hyper::proto::h1::conn] flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy }
TRACE [hyper::proto::h1::conn] flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy }
TRACE [hyper::proto::h1::conn] flushed({role=server}): State { reading: KeepAlive, writing: Init, keep_alive: Busy }
TRACE [mio::poll] deregistering handle with poller
TRACE [hyper::proto::h1::role] Server::encode status=200, body=Some(Known(6092)), req_method=Some(GET)
DEBUG [hyper::proto::h1::io] flushed 6196 bytes
TRACE [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
TRACE [hyper::proto::h1::conn] Conn::read_head
TRACE [hyper::proto::h1::conn] flushed({role=server}): State { reading: Init, writing: Init, keep_alive: Idle }
TRACE [hyper::proto::h1::conn] Conn::read_head
DEBUG [hyper::proto::h1::io] read 0 bytes
TRACE [hyper::proto::h1::io] parse eof
TRACE [hyper::proto::h1::conn] State::close_read()
DEBUG [hyper::proto::h1::conn] read eof
TRACE [hyper::proto::h1::conn] State::close_write()
TRACE [hyper::proto::h1::conn] State::close_read()
TRACE [hyper::proto::h1::conn] State::close_write()
TRACE [hyper::proto::h1::conn] flushed({role=server}): State { reading: Closed, writing: Closed, keep_alive: Disabled }
TRACE [hyper::proto::h1::conn] shut down IO complete
TRACE [mio::poll] deregistering handle with poller

Unbound logs
[1616564218] unbound[31164:1] debug: comm point start listening 23 (30000 msec)
[1616564218] unbound[31164:1] debug: Reading tcp query of length 21826
[1616564248] unbound[31164:1] debug: tcp took too long, dropped
[1616564248] unbound[31164:1] debug: close fd 23
[1616564269] unbound[31164:0] debug: comm point start listening 23 (30000 msec)
[1616564269] unbound[31164:0] debug: Reading tcp query of length 21826
[1616564299] unbound[31164:0] debug: tcp took too long, dropped
[1616564299] unbound[31164:0] debug: close fd 23

[svartalf]

What about this ==========> DEBUG [hyper::proto::h1::io] read 0 bytes
=====================> DEBUG [hyper::proto::h1::conn] read eof

These are okay, it is about your HTTP request to /metrics not having a request body (which is expected for GET requests).

Still same issue with the branch close-remote-control-socket

That is really unfortunate, I kinda expected it to fix the issue, but it also did not worked for me with unbound 1.9.4 (running through docker, not sure if it might affect the network behavior).

I just noted one thing: you posted the following execution command above:

./target/release/unbound-telemetry tcp --bind --log-level debug --control-interface 127.0.0.1:5053

but according from your post from below, port 5053 is used by unbound itself to serve DNS requests, while control interface should have the different port:

  control-port: <port number>
      The  port number to listen on for IPv4 or IPv6 control interfaces,
     default is 8953.  If you change this  and  permissions  have  been
       dropped,  you  must  restart  the  server  for  the change to take
       effect.

Can you check if it is provided in your unbound.conf first and then try to change command to the following:

./target/release/unbound-telemetry tcp --bind --log-level debug --control-interface 127.0.0.1:8953

Change 8953 port to whatever is set in your configuration for control-port option if it is provided.

[rambabubolla]

thanks now it is working fine with ./target/release/unbound-telemetry tcp --bind --log-level debug --control-interface 127.0.0.1:8953

[rambabubolla]

Is there Docker image available for unbound-telemetry ?

[svartalf]

Great to hear that it works!

As for Docker, you can use the Dockerfile from the repo, but there is no automatic process to publish images somewhere yet.

[svartalf]

For everyone who would find this topic later: double check that you are connecting to the control port (defined by the unbound control-port option) and not to the port intended to serve DNS requests.