[1545] Added logging to the DHCP4 server

src/bin/dhcp4/Makefile.am

@@ -12,7 +12,7 @@ endif
 
 pkglibexecdir = $(libexecdir)/@PACKAGE@
 
-CLEANFILES = spec_config.h
+CLEANFILES  = *.gcno *.gcda spec_config.h dhcp4_messages.h dhcp4_messages.cc
 
 man_MANS = b10-dhcp4.8
 DISTCLEANFILES = $(man_MANS)
@@ -35,11 +35,20 @@ endif
 spec_config.h: spec_config.h.pre
 	$(SED) -e "s|@@LOCALSTATEDIR@@|$(localstatedir)|" spec_config.h.pre >$@
 
-BUILT_SOURCES = spec_config.h
+dhcp4_messages.h dhcp4_messages.cc: dhcp4_messages.mes
+	$(top_builddir)/src/lib/log/compiler/message $(top_srcdir)/src/bin/dhcp4/dhcp4_messages.mes
+
+BUILT_SOURCES = spec_config.h dhcp4_messages.h dhcp4_messages.cc
+
 pkglibexec_PROGRAMS = b10-dhcp4
 
-b10_dhcp4_SOURCES = main.cc dhcp4_srv.cc dhcp4_srv.h
+b10_dhcp4_SOURCES  = main.cc
 b10_dhcp4_SOURCES += ctrl_dhcp4_srv.cc ctrl_dhcp4_srv.h
+b10_dhcp4_SOURCES += dhcp4_log.cc dhcp4_log.h
+b10_dhcp4_SOURCES += dhcp4_srv.cc dhcp4_srv.h
+
+nodist_b10_dhcp4_SOURCES = dhcp4_messages.h dhcp4_messages.cc
+EXTRA_DIST += dhcp4_messages.mes
 
 if USE_CLANGPP
 # Disable unused parameter warning caused by some of the
@@ -47,7 +56,7 @@ if USE_CLANGPP
 b10_dhcp4_CXXFLAGS = -Wno-unused-parameter
 endif
 
-b10_dhcp4_LDADD = $(top_builddir)/src/lib/dhcp/libb10-dhcp++.la
+b10_dhcp4_LDADD  = $(top_builddir)/src/lib/dhcp/libb10-dhcp++.la
 b10_dhcp4_LDADD += $(top_builddir)/src/lib/exceptions/libb10-exceptions.la
 b10_dhcp4_LDADD += $(top_builddir)/src/lib/asiolink/libb10-asiolink.la
 b10_dhcp4_LDADD += $(top_builddir)/src/lib/log/libb10-log.la

src/bin/dhcp4/ctrl_dhcp4_srv.cc

@@ -24,17 +24,18 @@
 #include <util/buffer.h>
 #include <dhcp4/spec_config.h>
 #include <dhcp4/ctrl_dhcp4_srv.h>
+#include <dhcp4/dhcp4_log.h>
 #include <dhcp/iface_mgr.h>
 #include <asiolink/asiolink.h>
 
-using namespace std;
-using namespace isc::util;
-using namespace isc::dhcp;
-using namespace isc::util;
-using namespace isc::data;
+using namespace isc::asiolink;
 using namespace isc::cc;
 using namespace isc::config;
-using namespace isc::asiolink;
+using namespace isc::data;
+using namespace isc::dhcp;
+using namespace isc::log;
+using namespace isc::util;
+using namespace std;
 
 namespace isc {
 namespace dhcp {
@@ -43,7 +44,8 @@ ControlledDhcpv4Srv* ControlledDhcpv4Srv::server_ = NULL;
 
 ConstElementPtr
 ControlledDhcpv4Srv::dhcp4ConfigHandler(ConstElementPtr new_config) {
-    cout << "b10-dhcp4: Received new config:" << new_config->str() << endl;
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_COMMAND, DHCP4_CONFIG_UPDATE)
+              .arg(new_config->str());
     ConstElementPtr answer = isc::config::createAnswer(0,
                              "Thank you for sending config.");
     return (answer);
@@ -51,13 +53,13 @@ ControlledDhcpv4Srv::dhcp4ConfigHandler(ConstElementPtr new_config) {
 
 ConstElementPtr
 ControlledDhcpv4Srv::dhcp4CommandHandler(const string& command, ConstElementPtr args) {
-    cout << "b10-dhcp4: Received new command: [" << command << "], args="
-         << args->str() << endl;
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_COMMAND, DHCP4_COMMAND_RECEIVED)
+              .arg(command).arg(args->str());
     if (command == "shutdown") {
         if (ControlledDhcpv4Srv::server_) {
             ControlledDhcpv4Srv::server_->shutdown();
         } else {
-            cout << "Server not initialized yet or already shut down." << endl;
+            LOG_WARN(dhcp4_logger, DHCP4_NOT_RUNNING);
             ConstElementPtr answer = isc::config::createAnswer(1,
                                      "Shutdown failure.");
             return (answer);
@@ -93,10 +95,9 @@ void ControlledDhcpv4Srv::establishSession() {
 
     /// @todo: Check if session is not established already. Throw, if it is.
 
-    cout << "b10-dhcp4: my specfile is " << specfile << endl;
-
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_START, DHCP4_CCSESSION_STARTING)
+              .arg(specfile);
     cc_session_ = new Session(io_service_.get_io_service());
-
     config_session_ = new ModuleCCSession(specfile, *cc_session_,
                                           dhcp4ConfigHandler,
                                           dhcp4CommandHandler, false);
@@ -106,8 +107,8 @@ void ControlledDhcpv4Srv::establishSession() {
     /// control with the "select" model of the DHCP server.  This is
     /// fully explained in \ref dhcpv4Session.
     int ctrl_socket = cc_session_->getSocketDesc();
-    cout << "b10-dhcp4: Control session started, socket="
-         << ctrl_socket << endl;
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_START, DHCP4_CCSESSION_STARTED)
+              .arg(ctrl_socket);
     IfaceMgr::instance().set_session_socket(ctrl_socket, sessionReader);
 }
 

src/bin/dhcp4/dhcp4_log.cc

@@ -0,0 +1,26 @@
+// 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.
+
+/// Defines the logger used by the top-level component of b10-dhcp4.
+
+#include "dhcp4_log.h"
+
+namespace isc {
+namespace dhcp {
+
+isc::log::Logger dhcp4_logger("dhcp4");
+
+} // namespace dhcp
+} // namespace isc
+

src/bin/dhcp4/dhcp4_log.h

@@ -0,0 +1,59 @@
+// 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.
+
+#ifndef __DHCP4_LOG__H
+#define __DHCP4_LOG__H
+
+#include <log/macros.h>
+#include <log/logger_support.h>
+#include <dhcp4/dhcp4_messages.h>
+
+namespace isc {
+namespace dhcp {
+
+/// \brief DHCP4 Logging
+///
+/// Defines the levels used to output debug messages in the non-library part of
+/// the b10-dhcp4 program.  Higher numbers equate to more verbose (and detailed)
+/// output.
+
+// Debug levels used to log information during startup and shutdown.
+const int DBG_DHCP4_START = DBGLVL_START_SHUT;
+const int DBG_DHCP4_SHUT = DBGLVL_START_SHUT;
+
+// Debug level used to log setting information (such as configuration changes).
+const int DBG_DHCP4_COMMAND = DBGLVL_COMMAND;
+
+// Trace basic operations within the code.
+const int DBG_DHCP4_BASIC = DBGLVL_TRACE_BASIC;
+
+// Trace detailed operations, including errors raised when processing invalid
+// packets.  (These are not logged at severities of WARN or higher for fear
+// that a set of deliberately invalid packets set to the server could overwhelm
+// the logging.)
+const int DBG_DHCP4_DETAIL = DBGLVL_TRACE_DETAIL;
+
+// This level is used to log the contents of packets received and sent.
+const int DBG_DHCP4_DETAIL_DATA = DBGLVL_TRACE_DETAIL_DATA;
+
+/// Define the logger for the "dhcp4" module part of b10-dhcp4.  We could define
+/// a logger in each file, but we would want to define a common name to avoid
+/// spelling mistakes, so it is just one small step from there to define a
+/// module-common logger.
+extern isc::log::Logger dhcp4_logger;
+
+} // namespace dhcp4
+} // namespace isc
+
+#endif // __DHCP4_LOG__H

src/bin/dhcp4/dhcp4_messages.mes

@@ -0,0 +1,109 @@
+# 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.
+
+$NAMESPACE isc::dhcp
+
+% DHCP4_CCSESSION_STARTED control channel session started on socket %1
+A debug message issued during startup after the IP4v DHCP server has
+successfully established a session with the BIND 10 control channel.
+
+% DHCP4_CCSESSION_STARTING starting control channel session, specfile: %1
+This debug message is issued just before the IPv4 DHCP server attempts to
+establish a session with the BIND 10 control channel.
+
+% DHCP4_COMMAND_RECEIVED received command %1, arguments: %2
+A debug message listing the command (and possible arguments) received from the
+BIND 10 control system.
+
+% DHCP4_CONFIG_UPDATE updated configuration received: %1
+A debug message indicating that the IPv4 DHCP server has received an updated
+configuration from the BIND 10 configuration system.
+
+% DHCP4_NOT_RUNNING IPv4 DHCP server is not running
+s warning message is issued when an attempt is made to shut down the IPv4 DHCP
+server but it is not running.
+
+% DHCP4_OPEN_SOCKET opening sockets on port %1
+A debug message issued during startup, this indicates that the IPv4 DHCP
+server is about to open sockets on the named port.
+
+% DHCP4_PACKET_DECLINE DECLINE packet received on interface %1
+The server has received a DECLINE packet on the specified interface.
+
+% DHCP4_PACKET_DISCOVER DISCOVER packet received on interface %1
+The server has received a DISCOVER packet on the specified interface.
+
+% DHCP4_PACKET_INFORM INFORM packet received on interface %1
+The server has received a DISCOVER packet on the specified interface.
+
+% DHCP4_PACKET_PARSE_FAIL failed to parse incoming packet: %1
+The server has received a packet that it is unable to interpret. The reason why
+the packet is invalid is include in the message.
+
+% DHCP4_PACKET_RELEASE RELEASE packet received on interface %1
+The server has received a RELEASE packet on the specified interface.
+
+% DHCP4_PACKET_REQUEST REQUEST packet received on interface %1
+The server has received a REQUEST packet on the specified interface.
+
+% DHCP4_PACKET_UNKNOWN unknown packet type (%1) received on interface %2
+Debug message indicating that the server has received an unknown packet type
+on the specified interface.  The type code is given in the message.  Note that
+this message will also be output if the server receives packet which is valid,
+but which should not be sent to the server (e.g. an OFFER or ACK).
+
+% DHCP4_PACK_FAIL failed to assemble message to be returned correctly
+This error is output if the server failed to assemble the data to be returned to the client into
+a valid packet.  Additional messages will detail the reason.
+
+% DHCP4_QUERY_DATA responding with packet type %1 data is <<%2>>
+A debug message listing the data returned to the client.
+
+% DHCP4_RESPONSE_DATA responding with packet type %1 data is <<%2>>
+A debug message listing the data returned to the client.
+
+% DHCP4_SERVER_FAILED server failed: %1
+The IPv4 DHCP server has encountered a fatal error and is terminating.
+The reason for the failure is included in the message.
+
+% DHCP4_SESSION_FAIL failed to establish BIND 10 session (%1), running stand-alone
+The server has failed to establish communication with the rest of BIND 10
+and is running in stand-alone mode.  (This behavior will change once the
+IPv4 DHCP server is properly integrated with the rest of BIND 10.)
+
+% DHCP4_SHUTDOWN server shutdown
+The IPv4 DHCP server has terminated normally.
+
+% DHCP4_SHUTDOWN_REQUEST shutdown of server requested
+This debug message indicates that a shutdown of the IPv4 server has been requested via a call
+to the 'shutdown' method of the core Dhcpv4Srv object.
+
+% DHCP4_SRV_CONSTRUCT_ERROR error creating Dhcpv4Srv object, reason: %1
+This error message indicates that during startup, the construction of a core
+component within the IPv4 DHCP server (the Dhcpv4 server object) has failed.
+As a result, the server will exit.  The reason for the failure is given
+within the message.
+
+% DHCP4_STANDALONE skipping message queue, running standalone
+This is a debug message indicating that the IPv4 server is running in standalone mode, not
+connected to the message queue.  Standalone mode is only useful during program development,
+and should not be used in a production environment.
+
+% DHCP4_STARTING server starting
+This informational message indicates that the IPv4 DHCP server has processed
+any command-line switches and is starting.
+
+% DHCP4_START_INFO pid: %1, port: %2, verbose: %3, standalone: %4
+This is a debug message issued during the IPv4 DHCP server startup.  It lists
+some information about the parameters with which the server is running.

src/bin/dhcp4/dhcp4_srv.cc

@@ -16,13 +16,15 @@
 #include <dhcp/pkt4.h>
 #include <dhcp/iface_mgr.h>
 #include <dhcp4/dhcp4_srv.h>
+#include <dhcp4/dhcp4_log.h>
 #include <asiolink/io_address.h>
 #include <dhcp/option4_addrlst.h>
 
-using namespace std;
 using namespace isc;
-using namespace isc::dhcp;
 using namespace isc::asiolink;
+using namespace isc::dhcp;
+using namespace isc::log;
+using namespace std;
 
 // These are hardcoded parameters. Currently this is a skeleton server that only
 // grants those options and a single, fixed, hardcoded lease.
@@ -35,8 +37,7 @@ const std::string HARDCODED_DOMAIN_NAME = "isc.example.com";
 const std::string HARDCODED_SERVER_ID = "192.0.2.1";
 
 Dhcpv4Srv::Dhcpv4Srv(uint16_t port) {
-    cout << "Initialization: opening sockets on port " << port << endl;
-
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_START, DHCP4_OPEN_SOCKET).arg(port);
     try {
         // first call to instance() will create IfaceMgr (it's a singleton)
         // it may throw something if things go wrong
@@ -47,8 +48,9 @@ Dhcpv4Srv::Dhcpv4Srv(uint16_t port) {
         IfaceMgr::instance().openSockets4(port);
 
         setServerID();
+
     } catch (const std::exception &e) {
-        cerr << "Error during DHCPv4 server startup: " << e.what() << endl;
+        LOG_ERROR(dhcp4_logger, DHCP4_SRV_CONSTRUCT_ERROR).arg(e.what());
         shutdown_ = true;
         return;
     }
@@ -57,12 +59,11 @@ Dhcpv4Srv::Dhcpv4Srv(uint16_t port) {
 }
 
 Dhcpv4Srv::~Dhcpv4Srv() {
-    cout << "b10-dhcp4: DHCPv4 server terminating." << endl;
     IfaceMgr::instance().closeSockets();
 }
 
 void Dhcpv4Srv::shutdown() {
-    cout << "b10-dhcp4: DHCPv4 server shutdown." << endl;
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_BASIC, DHCP4_SHUTDOWN_REQUEST);
     shutdown_ = true;
 }
 
@@ -79,39 +80,43 @@ Dhcpv4Srv::run() {
         if (query) {
             try {
                 query->unpack();
+
             } catch (const std::exception& e) {
-                /// TODO: Printout reasons of failed parsing
-                cout << "Failed to parse incoming packet " << endl;
+                // Failed to parse the packet.
+                LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL,
+                          DHCP4_PACKET_PARSE_FAIL).arg(e.what());
                 continue;
             }
+            LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL_DATA, DHCP4_QUERY_DATA)
+                      .arg(query->toText());
+
 
             switch (query->getType()) {
             case DHCPDISCOVER:
                 rsp = processDiscover(query);
                 break;
+
             case DHCPREQUEST:
                 rsp = processRequest(query);
                 break;
+
             case DHCPRELEASE:
                 processRelease(query);
                 break;
+
             case DHCPDECLINE:
                 processDecline(query);
                 break;
+
             case DHCPINFORM:
                 processInform(query);
                 break;
+
             default:
-                cout << "Unknown pkt type received:"
-                     << query->getType() << endl;
+                LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_UNKNOWN)
+                          .arg(query->getType()).arg(query->getIface());
             }
 
-            cout << "Received message type " << int(query->getType()) << endl;
-
-            // TODO: print out received packets only if verbose (or debug)
-            // mode is enabled
-            cout << query->toText();
-
             if (rsp) {
                 if (rsp->getRemoteAddr().toText() == "0.0.0.0") {
                     rsp->setRemoteAddr(query->getRemoteAddr());
@@ -127,12 +132,11 @@ Dhcpv4Srv::run() {
                 rsp->setIface(query->getIface());
                 rsp->setIndex(query->getIndex());
 
-                cout << "Replying with message type "
-                     << static_cast<int>(rsp->getType()) << ":" << endl;
-                cout << rsp->toText();
-                cout << "----" << endl;
-                if (rsp->pack()) {
-                    cout << "Packet assembled correctly." << endl;
+                LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL_DATA,
+                          DHCP4_RESPONSE_DATA)
+                          .arg(rsp->getType()).arg(rsp->toText());
+                if (!rsp->pack()) {
+                    LOG_ERROR(dhcp4_logger, DHCP4_PACK_FAIL);
                 }
                 IfaceMgr::instance().send(rsp);
             }
@@ -239,6 +243,8 @@ void Dhcpv4Srv::tryAssignLease(Pkt4Ptr& msg) {
 }
 
 Pkt4Ptr Dhcpv4Srv::processDiscover(Pkt4Ptr& discover) {
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_DISCOVER)
+              .arg(discover->getIface());
     Pkt4Ptr offer = Pkt4Ptr
         (new Pkt4(DHCPOFFER, discover->getTransid()));
 
@@ -252,6 +258,8 @@ Pkt4Ptr Dhcpv4Srv::processDiscover(Pkt4Ptr& discover) {
 }
 
 Pkt4Ptr Dhcpv4Srv::processRequest(Pkt4Ptr& request) {
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_REQUEST)
+              .arg(request->getIface());
     Pkt4Ptr ack = Pkt4Ptr
         (new Pkt4(DHCPACK, request->getTransid()));
 
@@ -265,16 +273,20 @@ Pkt4Ptr Dhcpv4Srv::processRequest(Pkt4Ptr& request) {
 }
 
 void Dhcpv4Srv::processRelease(Pkt4Ptr& release) {
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_RELEASE)
+              .arg(release->getIface());
     /// TODO: Implement this.
-    cout << "Received RELEASE on " << release->getIface() << " interface." << endl;
 }
 
 void Dhcpv4Srv::processDecline(Pkt4Ptr& decline) {
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_DECLINE)
+              .arg(decline->getIface());
     /// TODO: Implement this.
-    cout << "Received DECLINE on " << decline->getIface() << " interface." << endl;
 }
 
 Pkt4Ptr Dhcpv4Srv::processInform(Pkt4Ptr& inform) {
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_DETAIL, DHCP4_PACKET_INFORM)
+              .arg(inform->getIface());
     /// TODO: Currently implemented echo mode. Implement this for real
     return (inform);
 }

src/bin/dhcp4/main.cc

@@ -14,9 +14,9 @@
 
 #include <config.h>
 #include <iostream>
-#include <log/dummylog.h>
-#include <log/logger_support.h>
 #include <dhcp4/ctrl_dhcp4_srv.h>
+#include <dhcp4/dhcp4_log.h>
+#include <log/logger_support.h>
 #include <boost/lexical_cast.hpp>
 
 using namespace std;
@@ -59,11 +59,12 @@ main(int argc, char* argv[]) {
         switch (ch) {
         case 'v':
             verbose_mode = true;
-            isc::log::denabled = true;
             break;
+
         case 's':
             stand_alone = true;
             break;
+
         case 'p':
             try {
                 port_number = boost::lexical_cast<int>(optarg);
@@ -78,51 +79,47 @@ main(int argc, char* argv[]) {
                 usage();
             }
             break;
-        case ':':
+
         default:
             usage();
         }
     }
 
+    // Check for extraneous parameters.
+    if ((argc - optind) > 0) {
+        usage();
+    }
+
     // Initialize logging.  If verbose, we'll use maximum verbosity.
     isc::log::initLogger(DHCP4_NAME,
                          (verbose_mode ? isc::log::DEBUG : isc::log::INFO),
                          isc::log::MAX_DEBUG_LEVEL, NULL);
+    LOG_INFO(dhcp4_logger, DHCP4_STARTING);
+    LOG_DEBUG(dhcp4_logger, DBG_DHCP4_START, DHCP4_START_INFO)
+              .arg(getpid()).arg(port_number).arg(verbose_mode ? "yes" : "no")
+              .arg(stand_alone ? "yes" : "no" );
 
-    cout << "b10-dhcp4: My pid=" << getpid() << ", binding to port "
-         << port_number << ", verbose " << (verbose_mode?"yes":"no")
-         << ", stand-alone=" << (stand_alone?"yes":"no") << endl;
-
-    if (argc - optind > 0) {
-        usage();
-    }
 
     int ret = EXIT_SUCCESS;
-
     try {
-
-        cout << "[b10-dhcp4] Initiating DHCPv4 server operation." << endl;
-
-        /// @todo: pass verbose to the actul server once logging is implemented
         ControlledDhcpv4Srv server(port_number);
-
         if (!stand_alone) {
             try {
                 server.establishSession();
             } catch (const std::exception& ex) {
-                cerr << "Failed to establish BIND10 session. "
-                    "Running in stand-alone mode:" << ex.what() << endl;
+                LOG_ERROR(dhcp4_logger, DHCP4_SESSION_FAIL).arg(ex.what());
                 // Let's continue. It is useful to have the ability to run
                 // DHCP server in stand-alone mode, e.g. for testing
             }
         } else {
-            cout << "Skipping connection to the BIND10 msgq." << endl;
+            LOG_DEBUG(dhcp4_logger, DBG_DHCP4_START, DHCP4_STANDALONE);
         }
-
         server.run();
+        LOG_INFO(dhcp4_logger, DHCP4_SHUTDOWN);
+
     } catch (const std::exception& ex) {
-        cerr << "[b10-dhcp4] Server failed: " << ex.what() << endl;
         ret = EXIT_FAILURE;
+        LOG_FATAL(dhcp4_logger, DHCP4_SERVER_FAILED).arg(ex.what());
     }
 
     return (ret);

src/bin/dhcp4/tests/Makefile.am

@@ -47,6 +47,8 @@ if HAVE_GTEST
 TESTS += dhcp4_unittests
 
 dhcp4_unittests_SOURCES = ../dhcp4_srv.h ../dhcp4_srv.cc ../ctrl_dhcp4_srv.cc
+dhcp4_unittests_SOURCES += ../dhcp4_log.h ../dhcp4_log.cc
+dhcp4_unittests_SOURCES += ../dhcp4_messages.h ../dhcp4_messages.cc
 dhcp4_unittests_SOURCES += dhcp4_unittests.cc
 dhcp4_unittests_SOURCES += dhcp4_srv_unittest.cc
 dhcp4_unittests_SOURCES += ctrl_dhcp4_srv_unittest.cc

src/bin/dhcp4/tests/dhcp4_test.py

@@ -29,14 +29,21 @@ class TestDhcpv4Daemon(unittest.TestCase):
     def setUp(self):
         # don't redirect stdout/stderr here as we want to print out things
         # during the test
-        pass
+        #
+        # However, we do want to set the logging lock directory to somewhere
+        # to which we can write - use the current working directory.  We then
+        # set the appropriate environment variable.
+        lockdir_envvar = "B10_LOCKFILE_DIR_FROM_BUILD"
+        lockdir = os.getenv(lockdir_envvar)
+        if lockdir is None:
+            os.putenv(lockdir_envvar, os.getcwd())
 
     def tearDown(self):
         pass
 
     def runCommand(self, params, wait=1):
         """
-        This method runs dhcp4 and returns a touple: (returncode, stdout, stderr)
+        This method runs dhcp4 and returns a tuple: (returncode, stdout, stderr)
         """
         ## @todo: Convert this into generic method and reuse it in dhcp6
 
@@ -79,9 +86,9 @@ class TestDhcpv4Daemon(unittest.TestCase):
         fcntl.fcntl(fd, fcntl.F_SETFL, fl | os.O_NONBLOCK)
 
         # There's potential problem if b10-dhcp4 prints out more
-        # than 4k of text
+        # than 16kB of text
         try:
-            output = os.read(self.stdout_pipes[0], 4096)
+            output = os.read(self.stdout_pipes[0], 16384)
         except OSError:
             print("No data available from stdout")
             output = ""
@@ -91,7 +98,7 @@ class TestDhcpv4Daemon(unittest.TestCase):
             output = ""
 
         try:
-            error = os.read(self.stderr_pipes[0], 4096)
+            error = os.read(self.stderr_pipes[0], 16384)
         except OSError:
             print("No data available on stderr")
             error = ""
@@ -128,13 +135,13 @@ class TestDhcpv4Daemon(unittest.TestCase):
         print("      not that is can bind sockets correctly. Please ignore binding errors.")
 
         (returncode, output, error) = self.runCommand(["../b10-dhcp4", "-v"])
-
-        self.assertEqual( str(output).count("[b10-dhcp4] Initiating DHCPv4 server operation."), 1)
+        output_text = str(output) + str(error)
+        self.assertEqual(output_text.count("DHCP4_STARTING"), 1)
 
     def test_portnumber_0(self):
         print("Check that specifying port number 0 is not allowed.")
 
-        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-p', '0'])
+        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-v', '-p', '0'])
 
         # When invalid port number is specified, return code must not be success
         self.assertTrue(returncode != 0)
@@ -145,7 +152,7 @@ class TestDhcpv4Daemon(unittest.TestCase):
     def test_portnumber_missing(self):
         print("Check that -p option requires a parameter.")
 
-        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-p'])
+        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-v', '-p'])
 
         # When invalid port number is specified, return code must not be success
         self.assertTrue(returncode != 0)
@@ -156,7 +163,7 @@ class TestDhcpv4Daemon(unittest.TestCase):
     def test_portnumber_invalid1(self):
         print("Check that -p option is check against bogus port number (999999).")
 
-        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-p','999999'])
+        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-v', '-p','999999'])
 
         # When invalid port number is specified, return code must not be success
         self.assertTrue(returncode != 0)
@@ -167,7 +174,7 @@ class TestDhcpv4Daemon(unittest.TestCase):
     def test_portnumber_invalid2(self):
         print("Check that -p option is check against bogus port number (123garbage).")
 
-        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-p','123garbage'])
+        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-v', '-p','123garbage'])
 
         # When invalid port number is specified, return code must not be success
         self.assertTrue(returncode != 0)
@@ -178,28 +185,19 @@ class TestDhcpv4Daemon(unittest.TestCase):
     def test_portnumber_nonroot(self):
         print("Check that specifying unprivileged port number will work.")
 
-        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-s', '-p', '10057'])
-
-        # When invalid port number is specified, return code must not be success
-        # TODO: Temporarily commented out as socket binding on systems that do not have
-        #       interface detection implemented currently fails.
-        # self.assertTrue(returncode == 0)
-
-        # Check that there is an error message about invalid port number printed on stderr
-        self.assertEqual( str(output).count("opening sockets on port 10057"), 1)
+        # Check that there is a message about running with an unprivileged port
+        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-v', '-s', '-p', '10057'])
+        output_text = str(output) + str(error)
+        self.assertEqual(output_text.count("DHCP4_OPEN_SOCKET opening sockets on port 10057"), 1)
 
     def test_skip_msgq(self):
         print("Check that connection to BIND10 msgq can be disabled.")
 
-        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-s', '-p', '10057'])
-
-        # When invalid port number is specified, return code must not be success
-        # TODO: Temporarily commented out as socket binding on systems that do not have
-        #       interface detection implemented currently fails.
-        # self.assertTrue(returncode == 0)
-
-        # Check that there is an error message about invalid port number printed on stderr
-        self.assertEqual( str(output).count("Skipping connection to the BIND10 msgq."), 1)
+        # Check that the system outputs a message on one of its streams about running
+        # standalone.
+        (returncode, output, error) = self.runCommand(['../b10-dhcp4', '-v', '-s', '-p', '10057'])
+        output_text = str(output) + str(error)
+        self.assertEqual(output_text.count("DHCP4_STANDALONE"), 1)
 
 if __name__ == '__main__':
     unittest.main()