server crashed after reload - Secondary Server only, caching enabled...

Wed Oct 31 12:24:29 UTC 2012

On 2012-09-06 09:14, Christian 'wiwi' Wittenhorst wrote:
> Hello and greetings again...
>
> I need your assistance again: We're trying to use bind10 for a secondary
> server. I can add the zones, everything is fine.
>
> However, as soon as I enable caching, bind10 won't restart on the next
> reboot. If I don't enable caching, everything's just fine. Even after
> enabling caching the server works fine UNTIL the next reboot.

The problem is still present in the current snapshot 
(bind10-devel-20120816), it seems identical to: 
<http://bind10.isc.org/ticket/2245>

Part of the problem seems to be that a RRSIG is present for a RR has has 
been removed long time ago. It seems to be caused by a bug in our DNSSEC 
signer, but it should not crash Bind10 anyway...

2012-10-31 12:59:58.733 FATAL [b10-auth.auth] AUTH_SERVER_FAILED server 
failed: RRSIG is added without covered RRset for as34288.net.

as34288.net.            7200    IN      RRSIG   SSHFP 7 2 7200 
20120917042044 20120831011030 43405 as34288.net. 
zWGqGQr5AxLdZdX7+Xx6lwGGyBmT/jOR6H11ZXQ2/Qogv5zh86KO2x0X 
xnhCDSSSkQkAbVDNTqgx+uWVtaz10X8/BJXiAzJUOLGAB/iLKvPPI5tI 
2PJuTYfONy7LytWBkrSMmihUJcBXdmGKdNJ2edql6Y7PkX+z4deKSB9i mF0=

The current logs:

2012-10-31 12:59:58.545 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone 28.158.85.in-addr.arpa. (class IN)
2012-10-31 12:59:58.546 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone 29.158.85.in-addr.arpa. (class IN)
2012-10-31 12:59:58.546 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone 30.158.85.in-addr.arpa. (class IN)
2012-10-31 12:59:58.546 DEBUG [b10-cmdctl.cmdctl] CMDCTL_SEND_COMMAND 
sending command get_module_spec to module ConfigManager
2012-10-31 12:59:58.547 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone 31.158.85.in-addr.arpa. (class IN)
2012-10-31 12:59:58.547 DEBUG [b10-cmdctl.cmdctl] CMDCTL_COMMAND_SENT 
command 'get_module_spec' to module 'ConfigManager' was sent
2012-10-31 12:59:58.547 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone 6.2.0.0.8.8.0.4.1.0.0.2.ip6.arpa. (class IN)
2012-10-31 12:59:58.547 DEBUG [b10-cmdctl.cmdctl] CMDCTL_SEND_COMMAND 
sending command get_config to module ConfigManager
2012-10-31 12:59:58.548 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone 2.5.1.0.1.0.0.0.0.7.4.0.1.0.0.2.ip6.arpa. (class IN)
2012-10-31 12:59:58.548 DEBUG [b10-cmdctl.cmdctl] CMDCTL_COMMAND_SENT 
command 'get_config' to module 'ConfigManager' was sent
2012-10-31 12:59:58.549 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone 0.2.b.4.1.0.0.2.ip6.arpa. (class IN)
2012-10-31 12:59:58.549 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone 128/25.31.158.85.in-addr.arpa. (class IN)
2012-10-31 12:59:58.550 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone zeuz.ch. (class IN)
2012-10-31 12:59:58.550 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone nuc.su. (class IN)
2012-10-31 12:59:58.551 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone mae.su. (class IN)
2012-10-31 12:59:58.551 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone 179.233.109.in-addr.arpa. (class IN)
2012-10-31 12:59:58.552 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone 37.232.91.in-addr.arpa. (class IN)
2012-10-31 12:59:58.553 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone katlait.ch. (class IN)
2012-10-31 12:59:58.553 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_LOAD_ZONE 
loading zone katlait.com. (class IN)
2012-10-31 12:59:58.554 DEBUG [b10-zonemgr.zonemgr] ZONEMGR_STARTED 
zonemgr started
2012-10-31 12:59:58.732 DEBUG [b10-auth.datasrc] DATASRC_SQLITE_DROPCONN 
SQLite3Database is being deinitialized
2012-10-31 12:59:58.732 DEBUG [b10-auth.datasrc] 
DATASRC_SQLITE_CONNCLOSE Closing sqlite database
2012-10-31 12:59:58.732 DEBUG [b10-auth.datasrc] DATASRC_SQLITE_DROPCONN 
SQLite3Database is being deinitialized
2012-10-31 12:59:58.732 DEBUG [b10-auth.datasrc] 
DATASRC_SQLITE_CONNCLOSE Closing sqlite database
2012-10-31 12:59:58.732 DEBUG [b10-auth.datasrc] DATASRC_MEM_DESTROY 
destroying zone 'BIND.' in 'CH' class
2012-10-31 12:59:58.732 FATAL [b10-auth.auth] AUTH_SERVER_FAILED server 
failed: RRSIG is added without covered RRset for as34288.net.
2012-10-31 12:59:58.732 DEBUG [b10-auth.cc] CC_DISCONNECT disconnecting 
from message queue daemon
2012-10-31 12:59:58.732 DEBUG [b10-auth.datasrc] DATASRC_SQLITE_DROPCONN 
SQLite3Database is being deinitialized
2012-10-31 12:59:58.732 DEBUG [b10-auth.datasrc] 
DATASRC_SQLITE_CONNCLOSE Closing sqlite database
2012-10-31 12:59:58.733 DEBUG [b10-auth.datasrc] DATASRC_SQLITE_DROPCONN 
SQLite3Database is being deinitialized
2012-10-31 12:59:58.733 DEBUG [b10-auth.datasrc] 
DATASRC_SQLITE_CONNCLOSE Closing sqlite database
2012-10-31 12:59:58.733 DEBUG [b10-auth.datasrc] DATASRC_MEM_DESTROY 
destroying zone 'BIND.' in 'CH' class
2012-10-31 12:59:58.733 FATAL [b10-auth.auth] AUTH_SERVER_FAILED server 
failed: RRSIG is added without covered RRset for as34288.net.
2012-10-31 12:59:58.733 DEBUG [b10-auth.cc] CC_DISCONNECT disconnecting 
from message queue daemon
2012-10-31 12:59:58.734 INFO  [b10-boss.boss] 
BIND10_LOST_SOCKET_CONSUMER consumer 28 of sockets disconnected, 
considering all its sockets closed
2012-10-31 12:59:58.735 INFO  [b10-boss.boss] 
BIND10_LOST_SOCKET_CONSUMER consumer 26 of sockets disconnected, 
considering all its sockets closed
2012-10-31 12:59:58.736 INFO  [b10-boss.boss] BIND10_PROCESS_ENDED 
process 1901 of b10-auth-1 ended with status 256
2012-10-31 12:59:58.736 ERROR [b10-boss.boss] BIND10_COMPONENT_FAILED 
component b10-auth-1 (pid 1901) failed: process exited normally with 
exit status 256
2012-10-31 12:59:58.736 FATAL [b10-boss.boss] 
BIND10_COMPONENT_UNSATISFIED component b10-auth-1 is required to run and 
failed
2012-10-31 12:59:58.736 INFO  [b10-boss.boss] BIND10_SHUTDOWN stopping 
the server
2012-10-31 12:59:58.736 INFO  [b10-boss.boss] BIND10_CONFIGURATOR_STOP 
bind10 component configurator is shutting down
2012-10-31 12:59:58.736 DEBUG [b10-boss.boss] BIND10_CONFIGURATOR_BUILD 
building plan '{'b10-auth-0': ({'priority': 10, 'special': 'auth', 
'kind': 'needed'}, <isc.bind10.special_component.Auth object at 
0x7fd2a66e4790>), 'b10-auth-1': ({'priority': 10, 'special': 'auth', 
'kind': 'needed'}, <isc.bind10.special_component.Auth object at 
0x7fd2a6700650>), 'sockcreator': ({'priority': 200, 'special': 
'sockcreator', 'kind': 'core'}, 
<isc.bind10.special_component.SockCreator object at 0x7fd2a7189350>), 
'msgq': ({'priority': 199, 'special': 'msgq', 'kind': 'core'}, 
<isc.bind10.special_component.Msgq object at 0x7fd2a71893d0>), 
'b10-stats': ({'address': 'Stats', 'kind': 'dispensable'}, 
<isc.bind10.component.Component object at 0x7fd2a6700590>), 'b10-xfrin': 
({'priority': 10, 'kind': 'needed'}, <isc.bind10.component.Component 
object at 0x7fd2a6700ad0>), 'b10-zonemgr': ({'priority': 10, 'kind': 
'needed'}, <isc.bind10.component.Component object at 0x7fd2a6700b50>), 
'b10-cmdctl': ({'special': 'cmdctl', 'kind': 'needed'}, 
<isc.bind10.special_component.CmdCtl object at 0x7fd2a6700b10>), 
'cfgmgr': ({'priority': 198, 'special': 'cfgmgr', 'kind': 'core'}, 
<isc.bind10.special_component.CfgMgr object at 0x7fd2a7189390>)}' -> '{}'
2012-10-31 12:59:58.736 DEBUG [b10-boss.boss] BIND10_CONFIGURATOR_RUN 
running plan of 8 tasks
2012-10-31 12:59:58.736 INFO  [b10-boss.boss] BIND10_COMPONENT_STOP 
component b10-auth-0 is being stopped
2012-10-31 12:59:58.736 INFO  [b10-boss.boss] BIND10_STOP_PROCESS asking 
b10-auth-0 to shut down
2012-10-31 12:59:58.736 INFO  [b10-boss.boss] BIND10_COMPONENT_STOP 
component Socket creator is being stopped
2012-10-31 12:59:58.736 INFO  [b10-boss.boss] 
BIND10_SOCKCREATOR_TERMINATE terminating socket creator
2012-10-31 12:59:58.736 INFO  [b10-boss.boss] BIND10_COMPONENT_STOP 
component msgq is being stopped
2012-10-31 12:59:58.736 INFO  [b10-boss.boss] BIND10_COMPONENT_STOP 
component b10-stats is being stopped
2012-10-31 12:59:58.736 INFO  [b10-boss.boss] BIND10_STOP_PROCESS asking 
b10-stats to shut down
2012-10-31 12:59:58.737 INFO  [b10-boss.boss] BIND10_COMPONENT_STOP 
component b10-xfrin is being stopped
2012-10-31 12:59:58.737 INFO  [b10-boss.boss] BIND10_STOP_PROCESS asking 
b10-xfrin to shut down
2012-10-31 12:59:58.737 INFO  [b10-boss.boss] BIND10_COMPONENT_STOP 
component b10-zonemgr is being stopped
2012-10-31 12:59:58.737 INFO  [b10-boss.boss] BIND10_STOP_PROCESS asking 
b10-zonemgr to shut down
2012-10-31 12:59:58.737 INFO  [b10-boss.boss] BIND10_COMPONENT_STOP 
component b10-cmdctl is being stopped
2012-10-31 12:59:58.737 INFO  [b10-boss.boss] BIND10_STOP_PROCESS asking 
b10-cmdctl to shut down
2012-10-31 12:59:58.737 INFO  [b10-boss.boss] BIND10_COMPONENT_STOP 
component cfgmgr is being stopped
2012-10-31 12:59:58.737 INFO  [b10-boss.boss] BIND10_STOP_PROCESS asking 
cfgmgr to shut down
2012-10-31 12:59:58.738 INFO  [b10-stats.stats] 
STATS_RECEIVED_SHUTDOWN_COMMAND shutdown command received
2012-10-31 12:59:59.738 INFO  [b10-boss.boss] BIND10_PROCESS_ENDED 
process 1897 of Socket creator ended with status 0
2012-10-31 12:59:59.738 INFO  [b10-boss.boss] BIND10_PROCESS_ENDED 
process 1899 of cfgmgr ended with status 0
2012-10-31 12:59:59.739 INFO  [b10-boss.boss] BIND10_PROCESS_ENDED 
process 1900 of b10-auth-0 ended with status 256
2012-10-31 12:59:59.739 INFO  [b10-boss.boss] BIND10_PROCESS_ENDED 
process 1904 of b10-stats ended with status 0
2012-10-31 12:59:59.739 INFO  [b10-boss.boss] BIND10_PROCESS_ENDED 
process 1905 of b10-cmdctl ended with status 0
2012-10-31 12:59:59.739 INFO  [b10-boss.boss] BIND10_SEND_SIGTERM 
sending SIGTERM to msgq (PID 1898)
2012-10-31 12:59:59.739 INFO  [b10-boss.boss] BIND10_SEND_SIGTERM 
sending SIGTERM to b10-xfrin (PID 1902)
2012-10-31 12:59:59.739 INFO  [b10-boss.boss] BIND10_SEND_SIGTERM 
sending SIGTERM to b10-zonemgr (PID 1903)
2012-10-31 12:59:59.840 INFO  [b10-boss.boss] BIND10_PROCESS_ENDED 
process 1898 of msgq ended with status 0
2012-10-31 12:59:59.840 INFO  [b10-boss.boss] BIND10_PROCESS_ENDED 
process 1902 of b10-xfrin ended with status 0
2012-10-31 12:59:59.840 INFO  [b10-boss.boss] BIND10_PROCESS_ENDED 
process 1903 of b10-zonemgr ended with status 0
2012-10-31 12:59:59.840 INFO  [b10-boss.boss] BIND10_SHUTDOWN_COMPLETE 
all processes ended, shutdown complete