dmachard/python-unbound-console

"debug: control connection has bad magic string" with unbound 1.17.1

MightySlaytanic opened this issue · 5 comments

MightySlaytanic commented

Hi,
I've been using unbound-console for a lot of months without any issue in my own giannicostanzi/unbound2influxdb2 docker image and today I've updated my debian 11 installation with unbound to debian 12 and also Unbound got updated from 1.13.1-1+deb11u1 to 1.17.1-2. Unbound works and it's listening as always on control port 8953 but unbound-console receives a connection reset and unbound logs show the following error:

unbound: [3389:0] debug: control connection has bad magic string

Looking at unbound code we can see the following comment related to that message:

if( r != 6 || strncmp(magic, "UBCT", 4) != 0) {
		verbose(VERB_QUERY, "control connection has bad magic string");
		/* probably wrong tool connected, ignore it completely */
		return;
}

Could it be related to a breaking change in unbound that needs some tweak in unbound console? 1.17.1-2 is the only version available on bookworm (Debian 12) so I'll have to rollback my VM to Debian 11 in the meanwhile.

MightySlaytanic commented

@dmachard I've cloned my VM to make some tests and with an increased debug level it shows "unauthenticated remote control connection" before the bad magic string message. I'll try to understand what changed since v 1.13 where everything works fine.

Jun 17 07:56:50 DNS-Stack-Test-Clone unbound[152]: [152:0] debug: new control connection from ip4 10.0.0.206 port 48576 (len 16)
Jun 17 07:56:50 DNS-Stack-Test-Clone unbound[152]: [152:0] debug: comm point stop listening 34
Jun 17 07:56:50 DNS-Stack-Test-Clone unbound[152]: [152:0] debug: comm point start listening 34 (120000 msec)
Jun 17 07:56:50 DNS-Stack-Test-Clone unbound[152]: [152:0] debug: unauthenticated remote control connection
Jun 17 07:56:50 DNS-Stack-Test-Clone unbound[152]: [152:0] debug: control connection has bad magic string
Jun 17 07:56:50 DNS-Stack-Test-Clone unbound[152]: [152:0] debug: remote control operation completed
Jun 17 07:56:50 DNS-Stack-Test-Clone unbound[152]: [152:0] debug: comm_point_close of 34: event_del
Jun 17 07:56:50 DNS-Stack-Test-Clone unbound[152]: [152:0] debug: close fd 34

The error above should be given if cert/keys are not provided -> code

This code, with the specified certs and keys works in 1.13 but gets the above errors in 1.17:

            try:
                rc = RemoteControl(
                    host=host,
                    port=host_port,
                    server_cert = host_server_cert,
                    client_cert = host_client_cert,
                    client_key = host_client_key
                )

                output = rc.send_command(cmd="stats")
            except Exception as e:
                failure = True
                print(e, file=sys.stderr)
                print(f"[{datetime.now().strftime('%Y-%m-%d %H:%M:%S')}] Connection Error: Could not connect to {host}:{host_port}[ENC:{host_encryption_flag}]({host_name})",file=sys.stderr)
                continue
dmachard commented

can you share the exception raised with your example ?

MightySlaytanic commented 

> /home/gianni/unbound/venv/lib/python3.11/site-packages/unbound_console/remotecontrol.py(116)_get_remote_control_socket()->None
-> sock.connect((self.rc_host, self.rc_port))
(Pdb) step
ConnectionResetError: [Errno 104] Connection reset by peer
> /home/gianni/unbound/venv/lib/python3.11/site-packages/unbound_console/remotecontrol.py(121)send_command()
-> sock = self._get_remote_control_socket()
(Pdb) step
--Return--
> /home/gianni/unbound/venv/lib/python3.11/site-packages/unbound_console/remotecontrol.py(121)send_command()->None
-> sock = self._get_remote_control_socket()
(Pdb) next
ConnectionResetError: [Errno 104] Connection reset by peer> /home/gianni/unbound/unbound-to-influxdb2.py(182)<module>()
-> output = rc.send_command(cmd="stats")
(Pdb) next
> /home/gianni/unbound/unbound-to-influxdb2.py(183)<module>()
-> except Exception as e:
(Pdb) step> /home/gianni/unbound/unbound-to-influxdb2.py(184)<module>()
-> failure = True
(Pdb) step
> /home/gianni/unbound/unbound-to-influxdb2.py(185)<module>()
-> print(e, file=sys.stderr)
(Pdb) print(e)
[Errno 104] Connection reset by peer

The connections seems to be closed by unbound after the sock.connect and so, before even sending the magic string with the command.

Here you can find the full unbound2influxdb2 script: https://github.com/MightySlaytanic/unbound2influxdb2.git

MightySlaytanic commented

Hi @dmachard, the "issue" was absolutely NOT related to unbound_console. When upgrading from Debian 11 + Unbound 1.13 to Debian 12 + Unbound 1.17 the following file is added to the unbound config folder:

# cat /etc/unbound/unbound.conf.d/remote-control.conf
remote-control:
  control-enable: yes
  # by default the control interface is is 127.0.0.1 and ::1 and port 8953
  # it is possible to use a unix socket too
  control-interface: /run/unbound.ctl

The last row makes unbound answer to control queries only on the unix socket and every connection to port 8953 is established at the TCP/IP level but then it is closed with a TCP RST as soon as you try to establish the TLS session. It has been sufficient to comment the above line to make everything work again.

I'm sorry, it was my fault but I didn't expect to find a new file in /etc/unbound/unbound.conf.d :-/