bind10-devel-20120119 outgoing zone transfer failure

[Spain, Dr. Jeffry A.]

> Only responding to this point right now. How old is this /var/bind10-devel/zone.sqlite3 ?
Bind10 was installed on February 6, 2012, using the bind10-devel-20120119 release. The modification date on zone.sqlite is yesterday: -rw-r--r-- 1 bind root 20480 2012-02-21 09:28 zone.sqlite3
I installed sqlite from the Ubuntu Oneiric package libsqlite3-dev, which is derived from sqlite 3.7.7, which was released in June 2011.

> You may want to back it up and then run:
> compatcheck/sqlite3-difftbl-check.py /var/bind10-devel/zone.sqlite3

The compatibility check generated the following:
root at nsb0:~/bind10_install/bind10-devel-20120119/compatcheck# ./sqlite3-difftbl-check.py /var/bind10-devel/zone.sqlite3 
Found an older version of SQLite3 DB file: /var/bind10-devel/zone.sqlite3
Perform '/root/bind10_install/bind10-devel-20120119/compatcheck/sqlite3-difftbl-check.py --upgrade /var/bind10-devel/zone.sqlite3'
before continuing install.

> There was a sqlite3 database change in October that the above script detects and can fix (with --upgrade switch).

The upgrade generated no output, presumably indicating success. Below are the log entries generated when I restarted bind10 after the upgrade. The sqlite database gets opened and closed a number of times in rapid succession -- not sure what that means.

> The "make install" step should check that also.

I don't know what happened at that point, and didn't preserve the output. If you would like me to troubleshoot this, I can rebuild the server and capture the output from the build process. Please let me know.

I will get back to you on whether or not this database upgrade fixes the zone transfer problem. Thanks. Jeff.

----------

Bind10 restart log entries:
2012-02-22 13:23:42.297 DEBUG [b10-boss.boss] BIND10_STARTED_CC started configuration/command session
2012-02-22 13:23:42.297 INFO  [b10-boss.boss] BIND10_READING_BOSS_CONFIGURATION reading boss configuration
2012-02-22 13:23:42.297 INFO  [b10-boss.boss] BIND10_CONFIGURATOR_RECONFIGURE reconfiguring running components
2012-02-22 13:23:42.298 DEBUG [b10-boss.boss] BIND10_CONFIGURATOR_BUILD building plan '{'sockcreator': ({'priority': 200, 'kind': 'core', 'special': 'sockcreator'}, <isc.bind10.special_component.SockCreator object at 0x26e8350>), 'msgq': ({'priority': 199, 'kind': 'core', 'special': 'msgq'}, <isc.bind10.special_component.Msgq object at 0x26e8410>), 'cfgmgr': ({'priority': 198, 'kind': 'core', 'special': 'cfgmgr'}, <isc.bind10.special_component.CfgMgr object at 0x26e83d0>)}' -> '{'sockcreator': {'priority': 200, 'kind': 'core', 'special': 'sockcreator'}, 'msgq': {'priority': 199, 'kind': 'core', 'special': 'msgq'}, 'b10-cmdctl': {'kind': 'needed', 'special': 'cmdctl'}, 'b10-xfrout': {'kind': 'dispensable', 'address': 'Xfrout'}, 'b10-auth': {'kind': 'needed', 'special': 'auth'}, 'cfgmgr': {'priority': 198, 'kind': 'core', 'special': 'cfgmgr'}, 'b10-stats': {'kind': 'dispensable', 'address': 'Stats'}, 'b10-stats-httpd': {'kind': 'dispensable', 'address': 'StatsHttpd'}}'
2012-02-22 13:23:42.298 DEBUG [b10-boss.boss] BIND10_CONFIGURATOR_RUN running plan of 5 tasks
2012-02-22 13:23:42.298 INFO  [b10-boss.boss] BIND10_COMPONENT_START component b10-cmdctl is starting
2012-02-22 13:23:42.298 INFO  [b10-boss.boss] BIND10_STARTING_PROCESS starting process b10-cmdctl
2012-02-22 13:23:42.311 DEBUG [b10-boss.boss] BIND10_STARTED_PROCESS_PID started b10-cmdctl (PID 20962)
2012-02-22 13:23:42.311 INFO  [b10-boss.boss] BIND10_COMPONENT_START component b10-xfrout is starting
2012-02-22 13:23:42.311 INFO  [b10-boss.boss] BIND10_STARTING_PROCESS starting process b10-xfrout
2012-02-22 13:23:42.327 DEBUG [b10-boss.boss] BIND10_STARTED_PROCESS_PID started b10-xfrout (PID 20963)
2012-02-22 13:23:42.327 INFO  [b10-boss.boss] BIND10_COMPONENT_START component b10-auth is starting
2012-02-22 13:23:42.327 INFO  [b10-boss.boss] BIND10_STARTING_PROCESS starting process b10-auth
2012-02-22 13:23:42.334 DEBUG [b10-boss.boss] BIND10_STARTED_PROCESS_PID started b10-auth (PID 20964)
2012-02-22 13:23:42.335 INFO  [b10-boss.boss] BIND10_COMPONENT_START component b10-stats is starting
2012-02-22 13:23:42.335 INFO  [b10-boss.boss] BIND10_STARTING_PROCESS starting process b10-stats
2012-02-22 13:23:42.391 DEBUG [b10-boss.boss] BIND10_STARTED_PROCESS_PID started b10-stats (PID 20965)
2012-02-22 13:23:42.391 INFO  [b10-boss.boss] BIND10_COMPONENT_START component b10-stats-httpd is starting
2012-02-22 13:23:42.391 INFO  [b10-boss.boss] BIND10_STARTING_PROCESS starting process b10-stats-httpd
2012-02-22 13:23:42.417 DEBUG [b10-boss.boss] BIND10_STARTED_PROCESS_PID started b10-stats-httpd (PID 20966)
2012-02-22 13:23:42.419 INFO  [b10-boss.boss] BIND10_STARTUP_COMPLETE BIND 10 started
2012-02-22 13:23:42.518 DEBUG [b10-auth.auth] AUTH_CONFIG_CHANNEL_ESTABLISHED configuration session channel established
2012-02-22 13:23:42.518 DEBUG [b10-auth.auth] AUTH_XFRIN_CHANNEL_CREATED XFRIN session channel created
2012-02-22 13:23:42.518 DEBUG [b10-auth.cc] CC_ESTABLISH trying to establish connection with message queue daemon at /var/bind10-devel/msgq_socket
2012-02-22 13:23:42.518 DEBUG [b10-auth.cc] CC_ESTABLISHED successfully connected to message queue daemon
2012-02-22 13:23:42.519 DEBUG [b10-auth.auth] AUTH_XFRIN_CHANNEL_ESTABLISHED XFRIN session channel established
2012-02-22 13:23:42.519 DEBUG [b10-auth.auth] AUTH_STATS_CHANNEL_CREATED STATS session channel created
2012-02-22 13:23:42.519 DEBUG [b10-auth.cc] CC_ESTABLISH trying to establish connection with message queue daemon at /var/bind10-devel/msgq_socket
2012-02-22 13:23:42.519 DEBUG [b10-auth.cc] CC_ESTABLISHED successfully connected to message queue daemon
2012-02-22 13:23:42.519 DEBUG [b10-auth.auth] AUTH_STATS_CHANNEL_ESTABLISHED STATS session channel established
2012-02-22 13:23:42.519 DEBUG [b10-auth.server_common] SRVCOMM_SET_LISTEN setting addresses to listen to
2012-02-22 13:23:42.544 INFO  [b10-boss.boss] BIND10_SOCKET_GET requesting socket [::]:53 of type TCP from the creator
2012-02-22 13:23:42.550 INFO  [b10-boss.boss] BIND10_SOCKET_CREATED successfully created socket 18
2012-02-22 13:23:42.555 DEBUG [b10-auth.asiodns] ASIODNS_FD_ADD_TCP adding a new TCP server by opened fd 14
2012-02-22 13:23:42.556 INFO  [b10-boss.boss] BIND10_SOCKET_GET requesting socket [::]:53 of type UDP from the creator
2012-02-22 13:23:42.562 INFO  [b10-boss.boss] BIND10_SOCKET_CREATED successfully created socket 20
2012-02-22 13:23:42.563 DEBUG [b10-auth.asiodns] ASIODNS_FD_ADD_UDP adding a new UDP server by opened fd 15
2012-02-22 13:23:42.564 INFO  [b10-boss.boss] BIND10_SOCKET_GET requesting socket [0.0.0.0]:53 of type TCP from the creator
2012-02-22 13:23:42.564 INFO  [b10-boss.boss] BIND10_SOCKET_CREATED successfully created socket 21
2012-02-22 13:23:42.565 DEBUG [b10-auth.asiodns] ASIODNS_FD_ADD_TCP adding a new TCP server by opened fd 16
2012-02-22 13:23:42.565 INFO  [b10-boss.boss] BIND10_SOCKET_GET requesting socket [0.0.0.0]:53 of type UDP from the creator
2012-02-22 13:23:42.570 INFO  [b10-boss.boss] BIND10_SOCKET_CREATED successfully created socket 22
2012-02-22 13:23:42.571 DEBUG [b10-auth.asiodns] ASIODNS_FD_ADD_UDP adding a new UDP server by opened fd 17
2012-02-22 13:23:42.571 DEBUG [b10-auth.auth] AUTH_STATS_TIMER_SET statistics timer set to 60 second(s)
2012-02-22 13:23:42.571 DEBUG [b10-auth.auth] AUTH_DATA_SOURCE data source database file: /var/bind10-devel/zone.sqlite3
2012-02-22 13:23:42.571 DEBUG [b10-auth.datasrc] DATASRC_SQLITE_CREATE SQLite data source created
2012-02-22 13:23:42.571 DEBUG [b10-auth.datasrc] DATASRC_SQLITE_OPEN opening SQLite database '/var/bind10-devel/zone.sqlite3'
2012-02-22 13:23:42.573 DEBUG [b10-auth.datasrc] DATASRC_META_ADD adding a data source into meta data source
2012-02-22 13:23:42.573 DEBUG [b10-auth.auth] AUTH_LOAD_TSIG loading TSIG keys
2012-02-22 13:23:42.573 DEBUG [b10-auth.server_common] SRVCOMM_KEYS_INIT initializing TSIG keyring
2012-02-22 13:23:42.575 DEBUG [b10-auth.server_common] SRVCOMM_KEYS_UPDATE updating TSIG keyring
2012-02-22 13:23:42.575 DEBUG [b10-auth.auth] AUTH_CONFIG_CHANNEL_STARTED configuration session channel started
2012-02-22 13:23:42.575 INFO  [b10-auth.auth] AUTH_SERVER_STARTED server started
2012-02-22 13:23:42.584 DEBUG [b10-stats.stats] STATS_RECEIVED_NEW_CONFIG received new configuration: {'version': 2}
2012-02-22 13:23:42.585 INFO  [b10-stats.stats] STATS_STARTING starting
2012-02-22 13:23:42.585 DEBUG [b10-stats.stats] STATS_SEND_REQUEST_BOSS requesting boss to send statistics
2012-02-22 13:23:42.698 INFO  [b10-xfrout.xfrout] XFROUT_NEW_CONFIG Update xfrout configuration
2012-02-22 13:23:42.699 INFO  [b10-xfrout.xfrout] XFROUT_NEW_CONFIG_DONE Update xfrout configuration done
2012-02-22 13:23:42.708 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
2012-02-22 13:23:42.708 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/var/bind10-devel/zone.sqlite3'
2012-02-22 13:23:42.710 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
2012-02-22 13:23:42.710 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
2012-02-22 13:23:42.710 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
2012-02-22 13:23:42.711 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/var/bind10-devel/zone.sqlite3'
2012-02-22 13:23:42.712 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
2012-02-22 13:23:42.712 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
2012-02-22 13:23:42.712 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
2012-02-22 13:23:42.712 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/var/bind10-devel/zone.sqlite3'
2012-02-22 13:23:42.713 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
2012-02-22 13:23:42.713 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
2012-02-22 13:23:42.714 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
2012-02-22 13:23:42.714 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/var/bind10-devel/zone.sqlite3'
2012-02-22 13:23:42.715 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
2012-02-22 13:23:42.715 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
2012-02-22 13:23:42.716 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_NEWCONN SQLite3Database is being initialized
2012-02-22 13:23:42.716 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNOPEN Opening sqlite database file '/var/bind10-devel/zone.sqlite3'
2012-02-22 13:23:42.716 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_DROPCONN SQLite3Database is being deinitialized
2012-02-22 13:23:42.716 DEBUG [b10-xfrout.datasrc] DATASRC_SQLITE_CONNCLOSE Closing sqlite database
2012-02-22 13:23:42.759 DEBUG [b10-cmdctl.cmdctl] CMDCTL_SEND_COMMAND sending command get_module_spec to module ConfigManager
2012-02-22 13:23:42.761 DEBUG [b10-cmdctl.cmdctl] CMDCTL_COMMAND_SENT command 'get_module_spec' to module 'ConfigManager' was sent
2012-02-22 13:23:42.762 DEBUG [b10-cmdctl.cmdctl] CMDCTL_SEND_COMMAND sending command get_config to module ConfigManager
2012-02-22 13:23:42.763 DEBUG [b10-cmdctl.cmdctl] CMDCTL_COMMAND_SENT command 'get_config' to module 'ConfigManager' was sent
2012-02-22 13:23:42.813 DEBUG [b10-stats-httpd.stats-httpd] STATHTTPD_HANDLE_CONFIG reading configuration: {'version': 2}
2012-02-22 13:23:42.821 INFO  [b10-stats-httpd.stats-httpd] STATHTTPD_STARTED listening on 127.0.0.1#8000

Jeffry A. Spain
Network Administrator
Cincinnati Country Day School