Opened 7 years ago

Closed 6 years ago

Last modified 6 years ago

#714 closed defect (fixed)

cfgmgr crash on auth configuration failure

Reported by: jreed Owned by: jelte
Priority: medium Milestone: Sprint-20110712
Component: configuration Version:
Keywords: Cc:
CVSS Scoring: Parent Tickets:
Sensitive: no Defect Severity: N/A
Sub-Project: DNS Feature Depending on Ticket:
Estimated Difficulty: 3.0 Add Hours to Ticket: 0
Total Hours: 0 Internal?: no

Description

Using memory datasource, I loaded a root zone (AXFR'd from b.root-servers.net and manually removed trailing SOA). (On related note, I think a new dig has option to remove that SOA for me.)

> config set Auth/datasources/ [{"type": "memory", "zones":[{"file": "/Local/Users/jreed/J", "origin":"."}]}]
> config commit
Error:  
> 

That is a problem where cfgmgr/bindctl doesn't tell me the error.

b10-auth said the following and cfgmgr crashed (see traceback):

[b10-auth] error: Server configuration failed: Duplicate rrset: . 172800 IN RRSIG DNSKEY 8 0 172800 20110326235959 20110312000000 19036 . DBtUpYvH4F0MFi97znkJ04IWRRvkzI9lbD/vFiIylQlhsLho2iGqguWolly4P6pTSZw4rE10zd5g26wO4F2ckQafZiajmSAb4hZTYEOrgGVx/+Chs4XMXD9z4rXZUGFZsIMi1xYHJr16u9NbcxysB5DtXzKzpnzQ35n5L8TrKy7i3JWd3sedUv13K3+VA4J8cbgDaO3eW1KHsO7zBTliHPQVQhnxCOsh0WcvsQM0zxdF7SfRyzbe/K8/nK0rb+OYlU/f4CarwQy7wb0Uugo67nBI1+zCo3ENn5tDeaRikuL9j/vHz8LOL1KWr4WqtPa12sQ5zyA7pwPRGyazAb2Rzg==

Traceback (most recent call last):
  File "/Local/Users/jreed/opt/bind10/libexec/bind10-devel/b10-cfgmgr", line 90, in <module>
    sys.exit(main())
  File "/Local/Users/jreed/opt/bind10/libexec/bind10-devel/b10-cfgmgr", line 77, in main
    cm.run()
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/config/cfgmgr.py", line 431, in run
    answer = self.handle_msg(msg);
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/config/cfgmgr.py", line 400, in handle_msg
    answer = self._handle_set_config(arg)
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/config/cfgmgr.py", line 365, in _handle_set_config
    answer = self._handle_set_config_all(cmd[0])
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/config/cfgmgr.py", line 339, in _handle_set_config_all
    answer = self._handle_set_config_module(module, cmd[module])
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/config/cfgmgr.py", line 308, in _handle_set_config_module
    answer, env = self.cc.group_recvmsg(False, seq)
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/cc/session.py", line 247, in group_recvmsg
    env, msg  = self.recvmsg(nonblock, seq)
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/cc/session.py", line 114, in recvmsg
    msg = isc.cc.message.from_wire(data[header_length + 2:])
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/cc/message.py", line 38, in from_wire
    return json.loads(data.decode('utf8'))
  File "/Local/Users/jreed/opt/pkg/lib/python3.1/json/__init__.py", line 305, in loads
    return _default_decoder.decode(s)
  File "/Local/Users/jreed/opt/pkg/lib/python3.1/json/decoder.py", line 339, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/Local/Users/jreed/opt/pkg/lib/python3.1/json/decoder.py", line 355, in raw_decode
    obj, end = self.scan_once(s, idx)
ValueError: Invalid control character at: line 1 column 482 (char 482)
[b10-msgq] Closing socket fd 5
[b10-msgq] Receive error: EOF
[bind10] Process b10-cfgmgr (PID 94276) terminated, exit status = 256
[bind10] Resurrecting dead b10-cfgmgr process...

I am not sure if this is three different problems (maybe needs different tickets). I will start with assigning this to configuration component since it should not crash whether or not b10-auth can't use the zone.

Subtickets

Change History (17)

comment:1 Changed 6 years ago by jinmei

  • Defect Severity set to N/A
  • Milestone set to Next-Sprint-Proposed
  • Sub-Project set to DNS

comment:2 Changed 6 years ago by stephen

  • Milestone changed from Next-Sprint-Proposed to Sprint-20110712

comment:3 Changed 6 years ago by jelte

  • Owner set to jelte
  • Status changed from new to assigned

comment:4 Changed 6 years ago by jelte

I am not able to load the root zone (it fails on reading the DS record, i am able to load a root zone without any dnssec data), but I don't see the cfgmgr crash, so it seems the problem from the title of this ticket itself has been fixed.

comment:5 Changed 6 years ago by jelte

  • Owner changed from jelte to jreed

comment:6 Changed 6 years ago by jreed

  • Owner changed from jreed to UnAssigned

I reproduced this:

(log output and bindctl output mixed here)

macmini:bind10 jreed$ ~/opt/bind10/bin/bindctl          
["login success "] login as root
> config set Auth/datasources/ [{"type": "memory", "zones":[{"file": "/Local/Users/jreed/root.zone", "origin":"."}]}]
> 2011-06-29 08:09:01.240 DEBUG [b10-auth.cc] CC_GROUP_SEND sending message '{ "command": [ "set", { "stats_data": { "auth.queries.tcp": 0, "auth.queries.udp": 0 } } ] }' to group 'Stats'
2011-06-29 08:09:01.241 DEBUG [b10-auth.cc] CC_GROUP_RECEIVE trying to receive a message
2011-06-29 08:09:01.242 DEBUG [b10-auth.cc] CC_GROUP_RECEIVED message arrived ('
{ "from": "4e0b3fd1_7@macmini.lab.isc.org", "group": "Stats", "instance": "*", "reply": 0, "seq": 6, "to": "4e0b3fd1_6@macmini.lab.isc.org", "type": "send" }', '{ "result": [ 0 ] }')

> config commit
2011-06-29 08:09:05.998 DEBUG [b10-auth.cc] CC_GROUP_RECEIVE trying to receive a message
2011-06-29 08:09:05.999 DEBUG [b10-auth.cc] CC_GROUP_RECEIVED message arrived ('{ "from": "4e0b3fd0_2@macmini.lab.isc.org", "group": "Auth", "instance": "*", "seq": 35, "to": "*", "type": "send" }', '{ "command": [ "config_update", { "datasources": [ { "type": "memory", "zones": [ { "file": "/Local/Users/jreed/root.zone", "origin": "." } ] } ], "listen_on": [ { "address": "0.0.0.0", "port": 5300 } ] } ] }')
2011-06-29 08:09:05.999 DEBUG [b10-auth.datasrc] DATASRC_MEM_CREATE creating zone '.' in 'IN' class
2011-06-29 08:09:05.999 DEBUG [b10-auth.datasrc] DATASRC_MEM_ADD_ZONE adding zone './IN'
2011-06-29 08:09:05.999 DEBUG [b10-auth.datasrc] DATASRC_MEM_LOAD loading zone '.' from file '/Local/Users/jreed/root.zone'
2011-06-29 08:09:05.999 DEBUG [b10-auth.datasrc] DATASRC_MEM_ADD_RRSET adding RRset './SOA' into zone '.'
2011-06-29 08:09:05.999 DEBUG [b10-auth.datasrc] DATASRC_MEM_ADD_RRSET adding RRset './RRSIG' into zone '.'
2011-06-29 08:09:06.000 DEBUG [b10-auth.datasrc] DATASRC_MEM_ADD_RRSET adding RR

set './NSEC' into zone '.'
2011-06-29 08:09:06.000 DEBUG [b10-auth.datasrc] DATASRC_MEM_ADD_RRSET adding RRset './RRSIG' into zone '.'
2011-06-29 08:09:06.000 ERROR [b10-auth.datasrc] DATASRC_MEM_DUP_RRSET duplicate RRset './RRSIG'
2011-06-29 08:09:06.000 DEBUG [b10-auth.datasrc] DATASRC_MEM_DESTROY destroying zone '.' in 'IN' class
2011-06-29 08:09:06.000 ERROR [b10-auth.auth] AUTH_CONFIG_UPDATE_FAIL update of configuration failed: Server configuration failed: Duplicate rrset: . 172800 IN RRSIG DNSKEY 8 0 172800 20110705235959 20110620000000 19036 . AMe/ymdy0FNabVZ31QGW3C/mItogMx3gDTnaA+yCuVEPHcIdI9++c+gjYhqMv1z9nTOGHlQ4Z5w9SzjXW9eYBwshpGfAFj4pDnHIhLGsscLQ9NQAE7DdcJivK+XXLKrqlf/RpJt2FPfR3tpKa8W4TDKuEC/atlz7+c1C5nUbgUF15v93vpwy69TdKCbih/IN64H5oE7ez8DW/h/fI8sXIGqpKSHfiq8wJgjDMWR2fGy2oIu1BlqGI7tdX0/gUPy67RV7EJ5IxG4j9Paz++EUmxRLLvES5cR5E5TeGF6sWoJhDrZ2gSORl2F1QigYlwh49zGGpDP1DCB2MaDM3LkHkA==



2011-06-29 08:09:06.000 DEBUG [b10-auth.cc] CC_REPLY replying to message from '{ "from": "4e0b3fd0_2@macmini.lab.isc.org", "group": "Auth", "instance": "*", "seq": 35, "to": "*", "type": "send" }' with '{ "result": [ 1, "Server configuration failed: Duplicate rrset: . 172800 IN RRSIG DNSKEY 8 0 172800 20110705235959 20110620000000 19036 . AMe/ymdy0FNabVZ31QGW3C/mItogMx3gDTnaA+yCuVEPHcIdI9++c+gjYhqMv1z9nTOGHlQ4Z5w9SzjXW9eYBwshpGfAFj4pDnHIhLGsscLQ9NQAE7DdcJivK+XXLKrqlf/RpJt2FPfR3tpKa8W4TDKuEC/atlz7+c1C5nUbgUF15v93vpwy69TdKCbih/IN64H5oE7ez8DW/h/fI8sXIGqpKSHfiq8wJgjDMWR2fGy2oIu1BlqGI7tdX0/gUPy67RV7EJ5IxG4j9Paz++EUmxRLLvES5cR5E5TeGF6sWoJhDrZ2gSORl2F1QigYlwh49zGGpDP1DCB2MaDM3LkHkA==
" ] }'
2011-06-29 08:09:06.000 DEBUG [b10-auth.cc] CC_START_READ starting asynchronous read
Traceback (most recent call last):
  File "/Local/Users/jreed/opt/bind10/libexec/bind10-devel/b10-cfgmgr", line 107, in <module>
    sys.exit(main())
  File "/Local/Users/jreed/opt/bind10/libexec/bind10-devel/b10-cfgmgr", line 95, in main
    cm.run()
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/config/cfgmgr.py", line 491, in run
    answer = self.handle_msg(msg);
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/config/cfg
mgr.py", line 462, in handle_msg
    answer = self._handle_set_config(arg)
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/config/cfgmgr.py", line 427, in _handle_set_config
    answer = self._handle_set_config_all(cmd[0])
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/config/cfgmgr.py", line 399, in _handle_set_config_all
    answer = self._handle_set_config_module(module, cmd[module])
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/config/cfgmgr.py", line 380, in _handle_set_config_module
    answer, env = self.cc.group_recvmsg(False, seq)
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/cc/session.py", line 247, in group_recvmsg
    env, msg  = self.recvmsg(nonblock, seq)
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/cc/session.py", line 114, in recvmsg
    msg = isc.cc.message.from_wire(data[header_length + 2:])
  File "/Local/Users/jreed/opt/bind10/lib/python3.1/site-packages/isc/cc/message.py", line 38, in from_wire
    return json.loads(data.decode('utf8'))
  File "/Local/Users/jreed/opt/pkg/lib/python3.1/json/__init__.py", line 305, in loads
    return _default_decoder.decode(s)
  File "/Local/Users/jreed/opt/pkg/lib/python3.1/json/decoder.py", line 339, in 
decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/Local/Users/jreed/opt/pkg/lib/python3.1/json/decoder.py", line 355, in raw_decode
    obj, end = self.scan_once(s, idx)
ValueError: Invalid control character at: line 1 column 482 (char 482)
[b10-msgq] Closing socket fd 5
[b10-msgq] Receive error: EOF
[bind10] Process b10-cfgmgr (PID 46431) terminated, exit status = 256
[bind10] Resurrecting dead b10-cfgmgr process...
[bind10] Resurrected b10-cfgmgr (PID 46455)

Duplicate RRSET caused crash?

I ran named-checkzone (bind 9.8) and it complained of many missing and extra glue records. I will retry with the canonical output. (But regardless, cfgmgr should not crash.)

comment:7 Changed 6 years ago by jreed

  • Owner changed from UnAssigned to jelte

comment:8 Changed 6 years ago by jreed

Even with the canonical zone it appears to complain and crash the same.

comment:9 Changed 6 years ago by jelte

This does indeed appear to be several problems;

  1. Auth can't parse that file
  2. Auth then sends a response that cfgmgr doesn't seem to be able to parse
  3. Cfgmgr crashes on said (presumably bad) response

I think I have a fix now for number 3 here, but on my system i didn't see the crash in the first place, so while i did add a test that I *think* reproduces the problem, i'm not entirely sure :)

Anyway I pushed this, if this fixes at least the crash issue, we can get it reviewed and then create tickets for 1 and 2 (although perhaps 1 is simply a case of zone file parser being incomplete)

comment:10 Changed 6 years ago by jelte

Turns out i can in fact reproduce this. The fix does solve the crash issue, and I also found the problem: there's a newline (\n) in the message, which is not allowed in 'strict' json. Apart from the crash issue, i'll also make the JSON decoder accept non-strict data in this branch.

We should also get rid of the newline itself, which I think is added by RRset::toText() (or whatever it was). I think it shouldn't do that in the first place, but I'm not entirely sure which code depends on that \n being added, so we may want to put that in a separate ticket.

comment:11 Changed 6 years ago by jelte

Ah the newlines issue actually had a ticket already; #962

Last edited 6 years ago by jelte (previous) (diff)

comment:12 Changed 6 years ago by jelte

  • Owner changed from jelte to UnAssigned
  • Status changed from assigned to reviewing

comment:13 Changed 6 years ago by jreed

No more crash. I am at 9e72b16bcbfcdc819cbdc437feb10f73b1694107

(bindctl and bind10 --verbose output follow)

> config set Auth/datasources/ [{"type": "memory", "zones":[{"file": "/Local/Users/jreed/root.zone-canonical", "origin":"."}]}]
> config commit
2011-06-30 07:19:27.357 DEBUG [b10-auth.cc] CC_GROUP_RECEIVE trying to receive a message
2011-06-30 07:19:27.357 DEBUG [b10-auth.cc] CC_GROUP_RECEIVED message arrived ('{ "from": "4e0c85b4_2@macmini.lab.isc.org", "group": "Auth", "instance": "*", "seq": 35, "to": "*", "type": "send" }', '{ "command": [ "config_update", { "datasources": [ { "type": "memory", "zones": [ { "file": "/Local/Users/jreed/root.zone-canonical", "origin": "." } ] } ], "listen_on": [ { "address": "0.0.0.0", "port": 5300 } ] } ] }')
2011-06-30 07:19:27.358 DEBUG [b10-auth.datasrc] DATASRC_MEM_CREATE creating zone '.' in 'IN' class
2011-06-30 07:19:27.358 DEBUG [b10-auth.datasrc] DATASRC_MEM_ADD_ZONE adding zone './IN'
2011-06-30 07:19:27.358 DEBUG [b10-auth.datasrc] DATASRC_MEM_LOAD loading zone '.' from file '/Local/Users/jreed/root.zone-canonical'
2011-06-30 07:19:27.672 DEBUG [b10-auth.datasrc] DATASRC_MEM_ADD_RRSET adding RRset './SOA' into zone '.'
2011-06-30 07:19:27.672 DEBUG [b10-auth.datasrc] DATASRC_MEM_ADD_RRSET adding RRset './RRSIG' into zone '.'
2011-06-30 07:19:27.673 DEBUG [b10-auth.datasrc] DATASRC_MEM_ADD_RRSET adding RRset './NS' into zone '.'
2011-06-30 07:19:27.673 DEBUG [b10-auth.datasrc] DATASRC_MEM_ADD_RRSET adding RRset './RRSIG' into zone '.'
2011-06-30 07:19:27.673 ERROR [b10-auth.datasrc] DATASRC_MEM_DUP_RRSET duplicate RRset './RRSIG'
2011-06-30 07:19:27.674 DEBUG [b10-auth.datasrc] DATASRC_MEM_DESTROY destroying zone '.' in 'IN' class
2011-06-30 07:19:27.674 ERROR [b10-auth.auth] AUTH_CONFIG_UPDATE_FAIL update of configuration failed: Server configuration failed: Duplicate rrset: . 518400 IN RRSIG NS 8 0 518400 20110705000000 20110627230000 34525 . fkO2bhj1SOelIBIJliRzNjUlHZUS/UtC6G8X+6peCXSHUkbh+8+YvFfJB3Fw5ctdaSYipJkvvIGQoQ1OFKB8sslxoggBaevBHhTnhaRXx15SlbMDn+U09rXPMQPT/5TBTQvRp+7oCgWLuuD8H5TJ/9kRH8/NDbtyA8lfmkY82vg=

2011-06-30 07:19:27.674 DEBUG [b10-auth.cc] CC_REPLY replying to message from '{ "from": "4e0c85b4_2@macmini.lab.isc.org", "group": "Auth", "instance": "*", "seq": 35, "to": "*", "type": "send" }' with '{ "result": [ 1, "Server configuration failed: Duplicate rrset: . 518400 IN RRSIG NS 8 0 518400 20110705000000 20110627230000 34525 . fkO2bhj1SOelIBIJliRzNjUlHZUS/UtC6G8X+6peCXSHUkbh+8+YvFfJB3Fw5ctdaSYipJkvvIGQoQ1OFKB8sslxoggBaevBHhTnhaRXx15SlbMDn+U09rXPMQPT/5TBTQvRp+7oCgWLuuD8H5TJ/9kRH8/NDbtyA8lfmkY82vg=
" ] }'
2011-06-30 07:19:27.674 DEBUG [b10-auth.cc] CC_START_READ starting asynchronous read
Error: Server configuration failed: Duplicate rrset: . 518400 IN RRSIG NS 8 0 518400 20110705000000 20110627230000 34525 . fkO2bhj1SOelIBIJliRzNjUlHZUS/UtC6G8X+6peCXSHUkbh+8+YvFfJB3Fw5ctdaSYipJkvvIGQoQ1OFKB8sslxoggBaevBHhTnhaRXx15SlbMDn+U09rXPMQPT/5TBTQvRp+7oCgWLuuD8H5TJ/9kRH8/NDbtyA8lfmkY82vg=

Configuration not committed
>

comment:14 Changed 6 years ago by vorner

  • Owner changed from UnAssigned to vorner

comment:15 Changed 6 years ago by vorner

  • Owner changed from vorner to jelte

Hello

The code looks OK. I'd just propose to add a note in form „Taken as a no“ to the description of CFGMGR_BAD_UPDATE_RESPONSE_FROM_MODULE. It can be merged then if you agree.

Thank you.

comment:16 Changed 6 years ago by jelte

  • Resolution set to fixed
  • Status changed from reviewing to closed

Thanks, done and merged, closing ticket.

comment:17 Changed 6 years ago by stephen

  • Estimated Difficulty changed from 0.0 to 3
Note: See TracTickets for help on using tickets.