QPID-4577: Enable/disable high resolution log timestamps

From the self-test log file:
2013-02-12 15:33:53 [Broker] notice Changing log hires timestamp to 1
2013-02-12 15:33:53.219003940 [Broker] debug Broker::setLogHiresTimestamp()
...
2013-02-12 15:33:53.491318800 [Broker] notice Changing log hires timestamp to 0
2013-02-12 15:33:53 [Broker] debug Broker::setLogHiresTimestamp()




git-svn-id: https://svn.apache.org/repos/asf/qpid/trunk/qpid@1445358 13f79535-47bb-0310-9956-ffa450edef68

7 files changed, 131 insertions, 2 deletions

diff --git a/cpp/include/qpid/log/Logger.h b/cpp/include/qpid/log/Logger.h
index 9464fa52dd..8c4beb0785 100644
--- a/cpp/include/qpid/log/Logger.h
+++ b/cpp/include/qpid/log/Logger.h
@@ -95,6 +95,11 @@ class QPID_COMMON_CLASS_EXTERN Logger : private boost::noncopyable {
     /** Get the options used to configure the logger. */
     QPID_COMMON_INLINE_EXTERN const Options& getOptions() const { return options; }
 
+    /** Get the hires timestamp setting */
+    QPID_COMMON_EXTERN bool getHiresTimestamp();
+
+    /** Set the hires timestamp setting */
+    QPID_COMMON_EXTERN void setHiresTimestamp(bool setting);
 
   private:
     typedef boost::ptr_vector<Output> Outputs;
diff --git a/cpp/src/qpid/broker/Broker.cpp b/cpp/src/qpid/broker/Broker.cpp
index b28216f998..3db6221541 100644
--- a/cpp/src/qpid/broker/Broker.cpp
+++ b/cpp/src/qpid/broker/Broker.cpp
@@ -48,6 +48,8 @@
 #include "qmf/org/apache/qpid/broker/ArgsBrokerGetLogLevel.h"
 #include "qmf/org/apache/qpid/broker/ArgsBrokerQueueMoveMessages.h"
 #include "qmf/org/apache/qpid/broker/ArgsBrokerSetLogLevel.h"
+#include "qmf/org/apache/qpid/broker/ArgsBrokerGetLogHiresTimestamp.h"
+#include "qmf/org/apache/qpid/broker/ArgsBrokerSetLogHiresTimestamp.h"
 #include "qmf/org/apache/qpid/broker/ArgsBrokerSetTimestampConfig.h"
 #include "qmf/org/apache/qpid/broker/ArgsBrokerGetTimestampConfig.h"
 #include "qmf/org/apache/qpid/broker/EventExchangeDeclare.h"
@@ -558,7 +560,22 @@ Manageable::status_t Broker::ManagementMethod (uint32_t methodId,
           status = setTimestampConfig(a.i_receive, getManagementExecutionContext());
           break;
         }
-   default:
+
+    case _qmf::Broker::METHOD_GETLOGHIRESTIMESTAMP:
+    {
+        dynamic_cast<_qmf::ArgsBrokerGetLogHiresTimestamp&>(args).o_logHires = getLogHiresTimestamp();
+        QPID_LOG (debug, "Broker::getLogHiresTimestamp()");
+        status = Manageable::STATUS_OK;
+        break;
+    }
+    case _qmf::Broker::METHOD_SETLOGHIRESTIMESTAMP:
+    {
+        setLogHiresTimestamp(dynamic_cast<_qmf::ArgsBrokerSetLogHiresTimestamp&>(args).i_logHires);
+        QPID_LOG (debug, "Broker::setLogHiresTimestamp()");
+        status = Manageable::STATUS_OK;
+        break;
+    }
+    default:
         QPID_LOG (debug, "Broker ManagementMethod not implemented: id=" << methodId << "]");
         status = Manageable::STATUS_NOT_IMPLEMENTED;
         break;
@@ -982,6 +999,18 @@ std::string Broker::getLogLevel()
     return level;
 }
 
+void Broker::setLogHiresTimestamp(bool enabled)
+{
+    QPID_LOG(notice, "Changing log hires timestamp to " << enabled);
+    qpid::log::Logger::instance().setHiresTimestamp(enabled);
+}
+
+bool Broker::getLogHiresTimestamp()
+{
+    return qpid::log::Logger::instance().getHiresTimestamp();
+}
+
+
 boost::shared_ptr<ProtocolFactory> Broker::getProtocolFactory(const std::string& name) const {
     ProtocolFactoryMap::const_iterator i
         = name.empty() ? protocolFactories.begin() : protocolFactories.find(name);
diff --git a/cpp/src/qpid/broker/Broker.h b/cpp/src/qpid/broker/Broker.h
index 5c4c2a279f..e9f501a658 100644
--- a/cpp/src/qpid/broker/Broker.h
+++ b/cpp/src/qpid/broker/Broker.h
@@ -130,6 +130,8 @@ class Broker : public sys::Runnable, public Plugin::Target,
     void setStore ();
     void setLogLevel(const std::string& level);
     std::string getLogLevel();
+    void setLogHiresTimestamp(bool enabled);
+    bool getLogHiresTimestamp();
     void createObject(const std::string& type, const std::string& name,
                       const qpid::types::Variant::Map& properties, bool strict, const ConnectionState* context);
     void deleteObject(const std::string& type, const std::string& name,
diff --git a/cpp/src/qpid/log/Logger.cpp b/cpp/src/qpid/log/Logger.cpp
index 7c2e807ca9..7e7e1e94c1 100644
--- a/cpp/src/qpid/log/Logger.cpp
+++ b/cpp/src/qpid/log/Logger.cpp
@@ -177,4 +177,20 @@ void Logger::reconfigure(const std::vector<std::string>& selectors) {
 
 void Logger::setPrefix(const std::string& p) { prefix = p; }
 
+
+bool Logger::getHiresTimestamp()
+{
+    return flags & HIRES;
+}
+
+
+void Logger::setHiresTimestamp(bool setting)
+{
+    ScopedLock l(lock);
+    if (setting)
+        flags |= HIRES;
+    else
+        flags &= ~HIRES;
+}
+
 }} // namespace qpid::log
diff --git a/cpp/src/tests/CMakeLists.txt b/cpp/src/tests/CMakeLists.txt
index bc13e2ecdd..7f122891d0 100644
--- a/cpp/src/tests/CMakeLists.txt
+++ b/cpp/src/tests/CMakeLists.txt
@@ -319,6 +319,7 @@ if (BUILD_ACL)
   add_test (acl_tests ${shell} ${CMAKE_CURRENT_SOURCE_DIR}/run_acl_tests${test_script_suffix})
 endif (BUILD_ACL)
 add_test (dynamic_log_level_test ${shell} ${CMAKE_CURRENT_SOURCE_DIR}/dynamic_log_level_test${test_script_suffix})
+add_test (dynamic_log_hires_timestamp ${shell} ${CMAKE_CURRENT_SOURCE_DIR}/dynamic_log_hires_timestamp${test_script_suffix})
 if (BUILD_MSSQL)
   add_test (store_tests ${shell} ${CMAKE_CURRENT_SOURCE_DIR}/run_store_tests${test_script_suffix} MSSQL)
 endif (BUILD_MSSQL)
diff --git a/cpp/src/tests/Makefile.am b/cpp/src/tests/Makefile.am
index d035e1aaa8..3513e0a6d6 100644
--- a/cpp/src/tests/Makefile.am
+++ b/cpp/src/tests/Makefile.am
@@ -298,7 +298,7 @@ system_tests = qpid-client-test quick_perftest quick_topictest run_header_test q
 TESTS += start_broker $(system_tests) python_tests stop_broker \
   run_ha_tests run_federation_tests run_federation_sys_tests \
   run_acl_tests run_cli_tests dynamic_log_level_test \
-  run_queue_flow_limit_tests ipv6_test
+  dynamic_log_hires_timestamp run_queue_flow_limit_tests ipv6_test
 
 EXTRA_DIST +=								\
   run_test vg_check							\
@@ -325,6 +325,7 @@ EXTRA_DIST +=								\
   ring_queue_test							\
   run_ring_queue_test							\
   dynamic_log_level_test						\
+  dynamic_log_hires_timestamp                                           \
   qpid-ctrl								\
   CMakeLists.txt							\
   windows/DisableWin32ErrorWindows.cpp					\
diff --git a/cpp/src/tests/dynamic_log_hires_timestamp b/cpp/src/tests/dynamic_log_hires_timestamp
new file mode 100755
index 0000000000..afe79cc9b3
--- /dev/null
+++ b/cpp/src/tests/dynamic_log_hires_timestamp
@@ -0,0 +1,75 @@
+#!/bin/bash
+
+#
+# Licensed to the Apache Software Foundation (ASF) under one
+# or more contributor license agreements.  See the NOTICE file
+# distributed with this work for additional information
+# regarding copyright ownership.  The ASF licenses this file
+# to you under the Apache License, Version 2.0 (the
+# "License"); you may not use this file except in compliance
+# with the License.  You may obtain a copy of the License at
+# 
+#   http://www.apache.org/licenses/LICENSE-2.0
+# 
+# Unless required by applicable law or agreed to in writing,
+# software distributed under the License is distributed on an
+# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+# KIND, either express or implied.  See the License for the
+# specific language governing permissions and limitations
+# under the License.
+#
+
+# Run a simple test to verify dynamic log highres timestamp changes
+source ./test_env.sh
+test -d $PYTHON_DIR || { echo "Skipping python tests, no python dir."; exit 0; }
+
+LOG_FILE=hires_test.log
+trap cleanup EXIT
+
+cleanup() {
+    test -n "$PORT" && $QPIDD_EXEC --no-module-dir --quit --port $PORT
+}
+
+error() { 
+    echo $*;
+    exit 1;
+}
+
+rm -rf $LOG_FILE
+PORT=$($QPIDD_EXEC --auth=no --no-module-dir --daemon --port=0 --log-to-file $LOG_FILE) || error "Could not start broker"
+
+echo Broker for log highres timestamp test started on $PORT, pid is $($QPIDD_EXEC --no-module-dir --check --port $PORT)
+
+$srcdir/qpid-ctrl -b localhost:$PORT setLogLevel level='debug+:Broker' > /dev/null
+$srcdir/qpid-ctrl -b localhost:$PORT echo sequence=1 body=LOWRES > /dev/null
+$srcdir/qpid-ctrl -b localhost:$PORT setLogHiresTimestamp logHires='true' > /dev/null
+$srcdir/qpid-ctrl -b localhost:$PORT echo sequence=2 body=HI_RES > /dev/null
+$srcdir/qpid-ctrl -b localhost:$PORT setLogHiresTimestamp logHires='false' > /dev/null
+$srcdir/qpid-ctrl -b localhost:$PORT echo sequence=3 body=LOWRES > /dev/null
+
+# Expect 3 log entries with 'echo' in them
+if [[ $(grep echo $LOG_FILE | wc -l) -ne 3 ]]; then 
+   cat $LOG_FILE
+   error "Log content error - expected 3 echo log entries"
+fi
+
+# Lines 1 and 3 are length X
+# Line 2 is length X+10 because of timestamp addition
+LEN1=$(grep echo $LOG_FILE | grep \(1 | wc -m)
+LEN2=$(grep echo $LOG_FILE | grep \(2 | wc -m)
+LEN3=$(grep echo $LOG_FILE | grep \(3 | wc -m)
+EXPECTED_LEN2=$(( $LEN1 + 10 ))
+
+if [ $LEN1 -ne $LEN3 ]; then
+    cat $LOG_FILE
+    error "Log content error - expected echo 3 to be same line length as echo 1"
+fi
+
+if [ $LEN2 -ne $EXPECTED_LEN2 ]; then
+    cat $LOG_FILE
+    error "Log content error - expected echo 2 to be 10 characters longer than echo 1"
+fi
+
+rm -rf $LOG_FILE
+echo OK
+