[trac1154] Initial modifications

src/bin/zonemgr/Makefile.am

@@ -6,8 +6,10 @@ pkglibexec_SCRIPTS = b10-zonemgr
 
 b10_zonemgrdir = $(pkgdatadir)
 b10_zonemgr_DATA = zonemgr.spec
+pyexec_DATA = zonemgr_messages.py
 
-CLEANFILES = b10-zonemgr zonemgr.pyc zonemgr.spec
+CLEANFILES  = b10-zonemgr zonemgr.pyc zonemgr.spec
+CLEANFILES += zonemgr_messages.py zonemgr_messages.pyc
 
 man_MANS = b10-zonemgr.8
 EXTRA_DIST = $(man_MANS) b10-zonemgr.xml
@@ -19,6 +21,10 @@ b10-zonemgr.8: b10-zonemgr.xml
 
 endif
 
+# Build logging source file from message files
+zonemgr_messages.py: zonemgr_messages.mes
+	$(top_builddir)/src/lib/log/compiler/message -p $(top_srcdir)/src/bin/zonemgr/zonemgr_messages.mes
+
 zonemgr.spec: zonemgr.spec.pre
 	$(SED) -e "s|@@LOCALSTATEDIR@@|$(localstatedir)|" zonemgr.spec.pre >$@
 

src/bin/zonemgr/zonemgr.py.in

@@ -37,10 +37,16 @@ from isc.datasrc import sqlite3_ds
 from optparse import OptionParser, OptionValueError
 from isc.config.ccsession import *
 import isc.util.process
+from zonemgr_messages import *
 
 # Initialize logging for called modules.
-# TODO: Log messages properly
 isc.log.init("b10-zonemgr")
+logger = isc.log.Logger("zonemgr")
+
+# Constants for debug levels, to be removed when we have #1074.
+DBG_START_SHUT = 0
+DBG_ZONEMGR_COMMAND = 10
+DBG_ZONEMGR_BASIC = 40
 
 isc.util.process.rename()
 
@@ -81,13 +87,6 @@ REFRESH_OFFSET = 3
 RETRY_OFFSET = 4
 EXPIRED_OFFSET = 5
 
-# verbose mode
-VERBOSE_MODE = False
-
-def log_msg(msg):
-    if VERBOSE_MODE:
-        sys.stdout.write("[b10-zonemgr] %s\n" % str(msg))
-
 class ZonemgrException(Exception):
     pass
 
@@ -161,6 +160,7 @@ class ZonemgrRefresh:
     def zone_refresh_success(self, zone_name_class):
         """Update zone info after zone refresh success"""
         if (self._zone_not_exist(zone_name_class)):
+            logger.error(ZONEMGR_UNKNOWN_ZONE_SUCCESS, zone_name_class[0], zone_name_class[1])
             raise ZonemgrException("[b10-zonemgr] Zone (%s, %s) doesn't "
                                    "belong to zonemgr" % zone_name_class)
         self.zonemgr_reload_zone(zone_name_class)
@@ -171,6 +171,7 @@ class ZonemgrRefresh:
     def zone_refresh_fail(self, zone_name_class):
         """Update zone info after zone refresh fail"""
         if (self._zone_not_exist(zone_name_class)):
+            logger.error(ZONEMGR_UNKNOWN_ZONE_FAIL, zone_name_class[0], zone_name_class[1])
             raise ZonemgrException("[b10-zonemgr] Zone (%s, %s) doesn't "
                                    "belong to zonemgr" % zone_name_class)
         # Is zone expired?
@@ -183,6 +184,7 @@ class ZonemgrRefresh:
     def zone_handle_notify(self, zone_name_class, master):
         """Handle zone notify"""
         if (self._zone_not_exist(zone_name_class)):
+            logger.error(ZONEMGR_UNKNOWN_ZONE_NOTIFIED, zone_name_class[0], zone_name_class[1])
             raise ZonemgrException("[b10-zonemgr] Notified zone (%s, %s) "
                                    "doesn't belong to zonemgr" % zone_name_class)
         self._set_zone_notifier_master(zone_name_class, master)
@@ -195,10 +197,12 @@ class ZonemgrRefresh:
 
     def zonemgr_add_zone(self, zone_name_class):
         """ Add a zone into zone manager."""
-        log_msg("Loading zone (%s, %s)" % zone_name_class)
+
+        logger.debug(DBG_ZONEMGR_BASIC, ZONEMGR_LOAD_ZONE, zone_name_class[0], zone_name_class[1])
         zone_info = {}
         zone_soa = sqlite3_ds.get_zone_soa(str(zone_name_class[0]), self._db_file)
         if not zone_soa:
+            logger.error(ZONEMGR_NO_SOA, zone_name_class[0], zone_name_class[1])
             raise ZonemgrException("[b10-zonemgr] zone (%s, %s) doesn't have soa." % zone_name_class)
         zone_info["zone_soa_rdata"] = zone_soa[7]
         zone_info["zone_state"] = ZONE_OK
@@ -269,7 +273,7 @@ class ZonemgrRefresh:
             except isc.cc.session.SessionTimeout:
                 pass        # for now we just ignore the failure
         except socket.error:
-            sys.stderr.write("[b10-zonemgr] Failed to send to module %s, the session has been closed." % module_name)
+            logger.error(ZONEMGR_SEND_FAIL, module_name)
 
     def _find_need_do_refresh_zone(self):
         """Find the first zone need do refresh, if no zone need
@@ -278,7 +282,8 @@ class ZonemgrRefresh:
         zone_need_refresh = None
         for zone_name_class in self._zonemgr_refresh_info.keys():
             zone_state = self._get_zone_state(zone_name_class)
-            # If hasn't received refresh response but are within refresh timeout, skip the zone
+            # If hasn't received refresh response but are within refresh
+            # timeout, skip the zone
             if (ZONE_REFRESHING == zone_state and
                 (self._get_zone_refresh_timeout(zone_name_class) > self._get_current_time())):
                 continue
@@ -298,7 +303,7 @@ class ZonemgrRefresh:
 
     def _do_refresh(self, zone_name_class):
         """Do zone refresh."""
-        log_msg("Do refresh for zone (%s, %s)." % zone_name_class)
+        logger.debug(DBG_ZONEMGR_BASIC, ZONEMGR_REFRESH_ZONE, zone_name_class[0], zone_name_class[1])
         self._set_zone_state(zone_name_class, ZONE_REFRESHING)
         self._set_zone_refresh_timeout(zone_name_class, self._get_current_time() + self._max_transfer_timeout)
         notify_master = self._get_zone_notifier_master(zone_name_class)
@@ -355,7 +360,7 @@ class ZonemgrRefresh:
                 if e.args[0] == errno.EINTR:
                     (rlist, wlist, xlist) = ([], [], [])
                 else:
-                    sys.stderr.write("[b10-zonemgr] Error with select(); %s\n" % e)
+                    logger.error(ZONEMGR_SELECT_ERROR, e);
                     break
 
             for fd in rlist:
@@ -375,6 +380,7 @@ class ZonemgrRefresh:
         """
         # Small sanity check
         if self._running:
+            logger.error(ZONEMGR_TIMER_ALREADY_RUNNING)
             raise RuntimeError("Trying to run the timers twice at the same time")
 
         # Prepare the launch
@@ -399,6 +405,7 @@ class ZonemgrRefresh:
         called from a different thread.
         """
         if not self._running:
+            logger.error(ZONEMGR_TIMER_NOT_RUNNING)
             raise RuntimeError("Trying to shutdown, but not running")
 
         # Ask the thread to stop
@@ -560,17 +567,17 @@ class Zonemgr:
         # jitter should not be bigger than half of the original value
         if config_data.get('refresh_jitter') > 0.5:
             config_data['refresh_jitter'] = 0.5
-            log_msg("[b10-zonemgr] refresh_jitter is too big, its value will "
-                      "be set to 0.5")
-
+            logger.warn(ZONEMGR_JITTER_TOO_BIG)
 
     def _parse_cmd_params(self, args, command):
         zone_name = args.get("zone_name")
         if not zone_name:
+            logger.error(ZONEMGR_NO_ZONE_NAME)
             raise ZonemgrException("zone name should be provided")
 
         zone_class = args.get("zone_class")
         if not zone_class:
+            logger.error(ZONEMGR_NO_ZONE_CLASS)
             raise ZonemgrException("zone class should be provided")
 
         if (command != ZONE_NOTIFY_COMMAND):
@@ -578,6 +585,7 @@ class Zonemgr:
 
         master_str = args.get("master")
         if not master_str:
+            logger.error(ZONEMGR_NO_MASTER_ADDRESS)
             raise ZonemgrException("master address should be provided")
 
         return ((zone_name, zone_class), master_str)
@@ -593,7 +601,7 @@ class Zonemgr:
             """ Handle Auth notify command"""
             # master is the source sender of the notify message.
             zone_name_class, master = self._parse_cmd_params(args, command)
-            log_msg("Received notify command for zone (%s, %s)." % zone_name_class)
+            logger.debug(DBG_ZONEMGR_COMMAND, ZONEMGR_RECEIVE_NOTIFY, zone_name_class[0], zone_name_class[1])
             with self._lock:
                 self._zone_refresh.zone_handle_notify(zone_name_class, master)
             # Send notification to zonemgr timer thread
@@ -602,6 +610,7 @@ class Zonemgr:
         elif command == ZONE_XFRIN_SUCCESS_COMMAND:
             """ Handle xfrin success command"""
             zone_name_class = self._parse_cmd_params(args, command)
+            logger.debug(DBG_ZONEMGR_COMMAND, ZONEMGR_RECEIVE_XFRIN_SUCCESS, zone_name_class[0], zone_name_class[1])
             with self._lock:
                 self._zone_refresh.zone_refresh_success(zone_name_class)
             self._master_socket.send(b" ")# make self._slave_socket readble
@@ -609,14 +618,17 @@ class Zonemgr:
         elif command == ZONE_XFRIN_FAILED_COMMAND:
             """ Handle xfrin fail command"""
             zone_name_class = self._parse_cmd_params(args, command)
+            logger.debug(DBG_ZONEMGR_COMMAND, ZONEMGR_RECEIVE_XFRIN_FAILED, zone_name_class[0], zone_name_class[1])
             with self._lock:
                 self._zone_refresh.zone_refresh_fail(zone_name_class)
             self._master_socket.send(b" ")# make self._slave_socket readble
 
         elif command == "shutdown":
+            logger.debug(DBG_ZONEMGR_COMMAND, ZONEMGR_RECEIVE_SHUTDOWN)
             self.shutdown()
 
         else:
+            logger.warn(ZONEMGR_RECEIVE_UNKNOWN, str(command))
             answer = create_answer(1, "Unknown command:" + str(command))
 
         return answer
@@ -643,25 +655,30 @@ def set_cmd_options(parser):
 
 if '__main__' == __name__:
     try:
+        logger.debug(DBG_START_SHUT, ZONEMGR_STARTING)
         parser = OptionParser()
         set_cmd_options(parser)
         (options, args) = parser.parse_args()
         VERBOSE_MODE = options.verbose
+        if VERBOSE_MODE:
+            logger.set_severity("DEBUG", 99)
 
         set_signal_handler()
         zonemgrd = Zonemgr()
         zonemgrd.run()
     except KeyboardInterrupt:
-        sys.stderr.write("[b10-zonemgr] exit zonemgr process\n")
+        logger.info(ZONEMGR_KEYBOARD_INTERRUPT)
+
     except isc.cc.session.SessionError as e:
-        sys.stderr.write("[b10-zonemgr] Error creating zonemgr, "
-                           "is the command channel daemon running?\n")
+        logger.error(ZONEMGR_SESSION_ERROR)
+
     except isc.cc.session.SessionTimeout as e:
-        sys.stderr.write("[b10-zonemgr] Error creating zonemgr, "
-                           "is the configuration manager running?\n")
+        logger.error(ZONEMGR_SESSION_TIMEOUT)
+
     except isc.config.ModuleCCSessionError as e:
-        sys.stderr.write("[b10-zonemgr] exit zonemgr process: %s\n" % str(e))
+        logger.error(ZONEMGR_CCSESSION_ERROR, str(e))
 
     if zonemgrd and zonemgrd.running:
         zonemgrd.shutdown()
 
+    logger.debug(DBG_START_SHUT, ZONEMGR_SHUTDOWN)

src/bin/zonemgr/zonemgr_messages.mes

@@ -0,0 +1,135 @@
+# Copyright (C) 2011  Internet Systems Consortium, Inc. ("ISC")
+#
+# Permission to use, copy, modify, and/or distribute this software for any
+# purpose with or without fee is hereby granted, provided that the above
+# copyright notice and this permission notice appear in all copies.
+#
+# THE SOFTWARE IS PROVIDED "AS IS" AND ISC DISCLAIMS ALL WARRANTIES WITH
+# REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+# AND FITNESS.  IN NO EVENT SHALL ISC BE LIABLE FOR ANY SPECIAL, DIRECT,
+# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+# LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+# OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+# PERFORMANCE OF THIS SOFTWARE.
+
+# No namespace declaration - these constants go in the global namespace
+# of the zonemgr messages python module.
+
+% ZONEMGR_CCSESSION_ERROR command channel session error: %1
+An error was encountered on the command channel.  The message indicates
+the nature of the error.
+
+% ZONEMGR_JITTER_TOO_BIG refresh_jitter is too big, setting to 0.5
+The value specified in the configuration for the refresh jitter is too large
+so its value has been set to the maximum of 0.5.
+
+% ZONEMGR_KEYBOARD_INTERRUPT exiting zonemgr process as result of keyboard interrupt
+An informational message output when the zone manager was being run at a
+terminal and it was terminated via a keyboard interrupt signal.
+
+% ZONEMGR_LOAD_ZONE loading zone %1 (class %2)
+This is a debug message indicating that the zone of the specified class
+is being loaded into the zone manager.
+
+% ZONEMGR_NO_MASTER_ADDRESS internal BIND 10 command did not contain address of master
+A command received by the zone manager from another BIND 10 module did
+not contain the address of the master server from which a NOTIFY message
+was received.  This may be due to an internal programming error; please
+submit a bug report.
+
+% ZONEMGR_NO_SOA zone %1 (class %2) does not have an SOA record
+When loading the named zone of the specified class the zone manager
+discovered that the data did not contain an SOA record.  The load has
+been abandoned.
+
+% ZONEMGR_NO_ZONE_CLASS internal BIND 10 command did not contain class of zone
+A command received by the zone manager from another BIND 10 module did
+not contain the class of the zone on which the zone manager should act.
+This may be due to an internal programming error; please submit a
+bug report.
+
+% ZONEMGR_NO_ZONE_NAME internal BIND 10 command did not contain name of zone
+A command received by the zone manager from another BIND 10 module did
+not contain the name of the zone on which the zone manager should act.
+This may be due to an internal programming error; please submit a
+bug report.
+
+% ZONEMGR_RECEIVE_NOTIFY received NOTIFY command for zone %1 (class %2)
+This is a debug message indicating that the zone manager has received a
+NOTIFY command over the command channel.
+
+% ZONEMGR_RECEIVE_SHUTDOWN received SHUTDOWN command
+This is a debug message indicating that the zone manager has received a
+SHUTDOWN command over the command channel.
+
+% ZONEMGR_RECEIVE_UNKNOWN received unknown command '%1'
+This is a warning message indicating that the zone manager has received
+the stated command over the command channel.  This is not known to the
+zone zone manager and although the command is ignored, its receipt may
+indicate an internal error.  Please submit a bug report.
+
+% ZONEMGR_RECEIVE_XFRIN_FAILED received XFRIN FAILED command for zone %1 (class %2)
+This is a debug message indicating that the zone manager has received an
+XFRIN FAILED command over the command channel.
+
+% ZONEMGR_RECEIVE_XFRIN_SUCCESS received XFRIN SUCCESS command for zone %1 (class %2)
+This is a debug message indicating that the zone manager has received an
+XFRIN SUCCESS command over the command channel.
+
+% ZONEMGR_REFRESH_ZONE refreshing zone %1 (class %2)
+The zone manager is refreshing the named zone of the specified class
+with updated information.
+
+% ZONEMGR_SELECT_ERROR error with select(): %1
+An attempt to wait for input from a socket failed.  The failing operation
+is a call to the operating system's select() function, which failed for
+the given reason.
+
+% ZONEMGR_SEND_FAIL failed to send command to %1, session has been closed
+The zone manager attempted to send a command to the named BIND 10 module,
+but the send failed.  The session between the modules has been closed.
+
+% ZONEMGR_SESSION_ERROR unable to establish session to command channel daemon
+The zonemgr process was not able to be started because it could not
+connect to the command channel daemon.  The most usual cause of this
+problem is that the daemon is not running.
+
+% ZONEMGR_SESSION_TIMEOUT timeout on session to command channel daemon
+The zonemgr process was not able to be started because it timed out when
+connecting to the command channel daemon.  The most usual cause of this
+problem is that the daemon is not running.
+
+% ZONEMGR_SHUTDOWN zone manager has shut down
+A debug message, output when the zone manager has shut down completely.
+
+% ZONEMGR_STARTING zone manager starting
+A debug message output when the zone manager starts up.
+
+% ZONEMGR_TIMER_ALREADY_RUNNING trying to start a timer but one is already running
+This message is issued when an attempt is made to start a timer thread
+but the thread is already running.  It indicates either an error in the
+program logic or a problem with stopping a previous instance of the timer.
+Please submit a bug report.
+
+% ZONEMGR_TIMER_NOT_RUNNING trying to shutdown but zone manager is not running
+At attempt was made to stop the zone manager's internal timer thread
+but it was not running.  This may indicate an internal program error.
+Please submit a bug report.
+
+% ZONEMGR_UNKNOWN_ZONE_FAIL zone %1 (class %2) is not known to the zone manager
+An XFRIN operation has failed but the zone that was the subject of the
+operation is not being managed by the zone manager.  This may indicate
+an error in the program (as the operation should not have been initiated
+if this were the case).  Please submit a bug report.
+
+% ZONEMGR_UNKNOWN_ZONE_NOTIFY notified zone %1 (class %2) is not known to the zone manager
+A NOTIFY was received but the zone that was the subject of the operation
+is not being managed by the zone manager.  This may indicate an error
+in the program (as the operation should not have been initiated if this
+were the case).  Please submit a bug report.
+
+% ZONEMGR_UNKNOWN_ZONE_SUCCESS zone %1 (class %2) is not known to the zone manager
+An XFRIN operation has succeeded but the zone received is not being
+managed by the zone manager.  This may indicate an error in the program
+(as the operation should not have been initiated if this were the case).
+Please submit a bug report.