Adding experimental (and optional) support of log4cxx logging.
Also, adding a sample logging configuration
diff --git a/log4cxx.properties b/log4cxx.properties
new file mode 100644
index 0000000..ccf24a6
--- /dev/null
+++ b/log4cxx.properties
@@ -0,0 +1,17 @@
+# Set root logger level to DEBUG and its only appender to A1.
+log4j.rootLogger=ERROR, A1
+
+# A1 is set to be a ConsoleAppender.
+log4j.appender.A1=org.apache.log4j.ConsoleAppender
+
+# A1 uses PatternLayout.
+log4j.appender.A1.layout=org.apache.log4j.PatternLayout
+log4j.appender.A1.target=System.err
+#log4j.appender.A1.layout.ConversionPattern=%d{dd-MMM HH:MM:SS,SSS} %p %c %m%n
+log4j.appender.A1.layout.ConversionPattern=%d{h:m:s,SSS} %t %-10c{1} %m%n
+
+log4j.logger.SyncLogic = TRACE
+#log4j.logger.bgpparser=TRACE
+#log4j.logger.bgpparser.AttributeType=ERROR
+#log4j.logger.bgpparser.MRTCommonHeader=ERROR
+
diff --git a/model/sync-ccnx-wrapper.cc b/model/sync-ccnx-wrapper.cc
index d531971..0fdff74 100644
--- a/model/sync-ccnx-wrapper.cc
+++ b/model/sync-ccnx-wrapper.cc
@@ -21,14 +21,19 @@
*/
#include "sync-ccnx-wrapper.h"
+#include "sync-log.h"
#include <poll.h>
#include <boost/throw_exception.hpp>
+#include <boost/date_time/posix_time/posix_time.hpp>
+
typedef boost::error_info<struct tag_errmsg, std::string> errmsg_info_str;
typedef boost::error_info<struct tag_errmsg, int> errmsg_info_int;
using namespace std;
using namespace boost;
+INIT_LOGGER ("CcnxWrapper");
+
namespace Sync {
#ifdef _DEBUG_WRAPPER_
@@ -113,6 +118,7 @@
void
CcnxWrapper::ccnLoop ()
{
+ _LOG_FUNCTION (this);
while (m_running)
{
diff --git a/model/sync-diff-state-container.h b/model/sync-diff-state-container.h
index 9349e76..a5e5392 100644
--- a/model/sync-diff-state-container.h
+++ b/model/sync-diff-state-container.h
@@ -45,6 +45,7 @@
std::size_t
operator() (DigestConstPtr digest) const
{
+ // std::cout << "digest->getHash: " << digest->getHash () << " (" << *digest << ")" << std::endl;
return digest->getHash ();
}
};
@@ -54,6 +55,7 @@
bool
operator() (DigestConstPtr digest1, DigestConstPtr digest2) const
{
+ // std::cout << boost::cref(*digest1) << " == " << boost::cref(*digest2) << " : " << (*digest1 == *digest2) << std::endl;
return *digest1 == *digest2;
}
};
diff --git a/model/sync-log.cc b/model/sync-log.cc
new file mode 100644
index 0000000..0ddd95c
--- /dev/null
+++ b/model/sync-log.cc
@@ -0,0 +1,61 @@
+/* -*- Mode: C++; c-file-style: "gnu"; indent-tabs-mode:nil -*- */
+/*
+ * Copyright (c) 2012 University of California, Los Angeles
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 2 as
+ * published by the Free Software Foundation;
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
+ *
+ * Author: Zhenkai Zhu <zhenkai@cs.ucla.edu>
+ * 卞超轶 Chaoyi Bian <bcy@pku.edu.cn>
+ * Alexander Afanasyev <alexander.afanasyev@ucla.edu>
+ */
+
+#include "sync-log.h"
+
+#ifdef HAVE_LOG4CXX
+
+#include <log4cxx/logger.h>
+#include <log4cxx/basicconfigurator.h>
+#include <log4cxx/consoleappender.h>
+#include <log4cxx/patternlayout.h>
+#include <log4cxx/level.h>
+#include <log4cxx/propertyconfigurator.h>
+#include <log4cxx/defaultconfigurator.h>
+#include <log4cxx/helpers/exception.h>
+using namespace log4cxx;
+using namespace log4cxx::helpers;
+
+#include <unistd.h>
+
+void
+INIT_LOGGERS ()
+{
+ static bool configured = false;
+
+ if (configured) return;
+
+ if (access ("log4cxx.properties", R_OK)==0)
+ PropertyConfigurator::configureAndWatch ("log4cxx.properties");
+ else
+ {
+ PatternLayoutPtr layout (new PatternLayout ("%d{HH:mm:ss} %p %c{1} - %m%n"));
+ ConsoleAppenderPtr appender (new ConsoleAppender (layout));
+
+ BasicConfigurator::configure( appender );
+ Logger::getRootLogger()->setLevel (log4cxx::Level::getInfo ());
+ }
+
+ configured = true;
+}
+
+#endif
diff --git a/model/sync-log.h b/model/sync-log.h
new file mode 100644
index 0000000..a2fcd70
--- /dev/null
+++ b/model/sync-log.h
@@ -0,0 +1,71 @@
+/* -*- Mode: C++; c-file-style: "gnu"; indent-tabs-mode:nil -*- */
+/*
+ * Copyright (c) 2012 University of California, Los Angeles
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 2 as
+ * published by the Free Software Foundation;
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
+ *
+ * Author: Zhenkai Zhu <zhenkai@cs.ucla.edu>
+ * 卞超轶 Chaoyi Bian <bcy@pku.edu.cn>
+ * Alexander Afanasyev <alexander.afanasyev@ucla.edu>
+ */
+
+#ifndef SYNC_LOG_H
+#define SYNC_LOG_H
+
+#ifdef HAVE_LOG4CXX
+
+#include <log4cxx/logger.h>
+
+#define INIT_LOGGER(name) \
+ static log4cxx::LoggerPtr staticModuleLogger = log4cxx::Logger::getLogger (name);
+
+#define _LOG_DEBUG(x) \
+ LOG4CXX_DEBUG(staticModuleLogger, x);
+
+#define _LOG_TRACE(x) \
+ LOG4CXX_TRACE(staticModuleLogger, x);
+
+#define _LOG_FUNCTION(x) \
+ LOG4CXX_TRACE(staticModuleLogger, __FUNCTION__ << "(" << x << ")");
+
+#define _LOG_FUNCTION_NOARGS \
+ LOG4CXX_TRACE(staticModuleLogger, __FUNCTION__ << "()");
+
+void
+INIT_LOGGERS ();
+
+#else
+
+#define INIT_LOGGER(name)
+#define _LOG_FUNCTION(x)
+#define _LOG_FUNCTION_NOARGS
+#define _LOG_TRACE(x)
+#define INIT_LOGGERS(x)
+
+#ifdef _DEBUG
+
+#include <boost/thread/thread.hpp>
+#include <boost/date_time/posix_time/posix_time.hpp>
+#include <iostream>
+
+#define _LOG_DEBUG(x) \
+ std::clog << boost::get_system_time () << " " << boost::this_thread::get_id () << " " << x << endl;
+
+#else
+#define _LOG_DEBUG(x)
+#endif
+
+#endif // HAVE_LOG4CXX
+
+#endif // SYNC_LOG_H
diff --git a/model/sync-logic.cc b/model/sync-logic.cc
index c81f2f1..088f8e3 100644
--- a/model/sync-logic.cc
+++ b/model/sync-logic.cc
@@ -23,6 +23,8 @@
#include "sync-logic.h"
#include "sync-diff-leaf.h"
#include "sync-full-leaf.h"
+#include "sync-log.h"
+
#include <boost/make_shared.hpp>
#include <boost/foreach.hpp>
#include <boost/lexical_cast.hpp>
@@ -32,6 +34,8 @@
using namespace std;
using namespace boost;
+INIT_LOGGER ("SyncLogic");
+
namespace Sync
{
@@ -43,16 +47,21 @@
, m_onRemove (onRemove)
, m_ccnxHandle(new CcnxWrapper())
, m_randomGenerator (static_cast<unsigned int> (std::time (0)))
- , m_rangeUniformRandom (m_randomGenerator, uniform_int<> (20,100))
+ , m_rangeUniformRandom (m_randomGenerator, uniform_int<> (10,50))
{
+ _LOG_FUNCTION (syncPrefix);
+
m_ccnxHandle->setInterestFilter (m_syncPrefix,
bind (&SyncLogic::respondSyncInterest, this, _1));
- sendSyncInterest ();
+ m_scheduler.schedule (posix_time::seconds (0),
+ bind (&SyncLogic::sendSyncInterest, this),
+ REEXPRESSING_INTEREST);
}
SyncLogic::~SyncLogic ()
{
+ _LOG_FUNCTION (this);
// cout << "SyncLogic::~SyncLogic ()" << endl;
m_ccnxHandle.reset ();
@@ -61,6 +70,7 @@
void
SyncLogic::respondSyncInterest (const string &interest)
{
+ _LOG_TRACE ("<< I " << interest);
//cout << "Respond Sync Interest" << endl;
string hash = interest.substr(interest.find_last_of("/") + 1);
// cout << "Received Sync Interest: " << hash << endl;
@@ -77,36 +87,47 @@
return;
}
- processSyncInterest (digest, interest);
+ processSyncInterest (digest, interest, false);
}
void
SyncLogic::processSyncInterest (DigestConstPtr digest, const std::string &interestName, bool timedProcessing/*=false*/)
{
- // cout << "SyncLogic::processSyncInterest " << timedProcessing << endl;
recursive_mutex::scoped_lock lock (m_stateMutex);
- if (*m_state.getDigest() == *digest)
- {
- // cout << interestName << "\n";
- m_syncInterestTable.insert (interestName);
- return;
- }
-
// Special case when state is not empty and we have received request with zero-root digest
- if (digest->isZero ())
+ if (digest->isZero () && !m_state.getDigest()->isZero ())
{
+ _LOG_TRACE (">> D " << interestName << "/state" << " (zero)");
+
m_ccnxHandle->publishData (interestName + "/state",
lexical_cast<string> (m_state),
m_syncResponseFreshness);
return;
}
+ if (*m_state.getDigest() == *digest)
+ {
+ // cout << interestName << "\n";
+ if (digest->isZero ())
+ {
+ _LOG_TRACE ("Digest is zero, adding /state to PIT");
+ m_syncInterestTable.insert (interestName + "/state");
+ }
+ else
+ {
+ _LOG_TRACE ("Same state. Adding to PIT");
+ m_syncInterestTable.insert (interestName);
+ }
+ return;
+ }
DiffStateContainer::iterator stateInDiffLog = m_log.find (digest);
if (stateInDiffLog != m_log.end ())
{
+ _LOG_TRACE (">> D " << interestName);
+
m_ccnxHandle->publishData (interestName,
lexical_cast<string> (*(*stateInDiffLog)->diff ()),
m_syncResponseFreshness);
@@ -115,6 +136,7 @@
if (!timedProcessing)
{
+ _LOG_DEBUG ("hmm");
m_scheduler.schedule (posix_time::milliseconds (m_rangeUniformRandom ()) /*from 20 to 100ms*/,
bind (&SyncLogic::processSyncInterest, this, digest, interestName, true),
DELAYED_INTEREST_PROCESSING);
@@ -122,6 +144,8 @@
}
else
{
+ _LOG_TRACE (">> D " << interestName << "/state" << " (timed processing)");
+
m_ccnxHandle->publishData (interestName + "/state",
lexical_cast<string> (m_state),
m_syncResponseFreshness);
@@ -131,7 +155,7 @@
void
SyncLogic::processSyncData (const string &name, const string &dataBuffer)
{
- // cout << "Process Sync Data" << endl;
+ _LOG_TRACE ("<< D " << name);
DiffStatePtr diffLog = make_shared<DiffState> ();
try
@@ -243,6 +267,7 @@
ss << *diffLog;
for (vector<string>::iterator ii = pis.begin(); ii != pis.end(); ++ii)
{
+ _LOG_TRACE (">> D " << *ii);
m_ccnxHandle->publishData (*ii, ss.str(), m_syncResponseFreshness);
}
}
@@ -260,6 +285,7 @@
m_log.erase (m_state.getDigest()); // remove diff state with the same digest. next pointers are still valid
/// @todo Optimization
m_log.insert (diffLog);
+ _LOG_DEBUG (*diffLog->getDigest () << " " << m_log.size ());
}
void
@@ -303,12 +329,14 @@
void
SyncLogic::sendSyncInterest ()
{
- //cout << "Sending Sync Interest" << endl;
+ // cout << "Sending Sync Interest" << endl;
recursive_mutex::scoped_lock lock (m_stateMutex);
ostringstream os;
os << m_syncPrefix << "/" << *m_state.getDigest();
+ _LOG_TRACE (">> I " << os.str ());
+
m_ccnxHandle->sendInterest (os.str (),
bind (&SyncLogic::processSyncData, this, _1, _2));
diff --git a/model/sync-scheduler.cc b/model/sync-scheduler.cc
index c5f1ca0..f54f91f 100644
--- a/model/sync-scheduler.cc
+++ b/model/sync-scheduler.cc
@@ -21,11 +21,13 @@
*/
#include "sync-scheduler.h"
-#include <boost/date_time/posix_time/posix_time.hpp>
+#include "sync-log.h"
using namespace boost;
using namespace std;
+INIT_LOGGER ("Scheduler");
+
namespace Sync {
Scheduler::Scheduler ()
@@ -45,6 +47,7 @@
void
Scheduler::threadLoop ()
{
+ _LOG_FUNCTION (this);
while (m_threadRunning)
{
try
diff --git a/test/test_app_socket.cc b/test/test_app_socket.cc
index 3f952c2..4773c36 100644
--- a/test/test_app_socket.cc
+++ b/test/test_app_socket.cc
@@ -25,6 +25,9 @@
using boost::test_tools::output_test_stream;
#include <boost/make_shared.hpp>
+#include <boost/date_time/posix_time/posix_time.hpp>
+
+#include "../model/sync-log.h"
#include "../model/sync-app-socket.h"
extern "C" {
@@ -35,6 +38,8 @@
using namespace std;
using namespace boost;
+INIT_LOGGER ("Test::AppSocket");
+
class TestSocketApp {
public:
map<string, string> data;
@@ -62,58 +67,67 @@
BOOST_AUTO_TEST_CASE (AppSocketTest)
{
-
+ INIT_LOGGERS ();
+
TestSocketApp a1, a2, a3;
string syncPrefix("/let/us/sync");
string p1("/irl.cs.ucla.edu"), p2("/yakshi.org"), p3("/google.com");
+ _LOG_DEBUG ("s1");
SyncAppSocket s1 (syncPrefix, bind(&TestSocketApp::set, &a1, _1, _2));
- this_thread::sleep (posix_time::milliseconds (500));
+ this_thread::sleep (posix_time::milliseconds (50));
+ _LOG_DEBUG ("s2");
SyncAppSocket s2 (syncPrefix, bind(&TestSocketApp::set, &a2, _1, _2));
- // SyncAppSocket s3 (syncPrefix, bind(&TestSocketApp::set, &a3, _1, _2));
+ this_thread::sleep (posix_time::milliseconds (50));
+ SyncAppSocket s3 (syncPrefix, bind(&TestSocketApp::set, &a3, _1, _2));
+ this_thread::sleep (posix_time::milliseconds (50));
// single source
string data0 = "Very funny Scotty, now beam down my clothes";
+ _LOG_DEBUG ("s1 publish");
s1.publish (p1, 0, data0, 10);
- this_thread::sleep (posix_time::milliseconds (1));
+ this_thread::sleep (posix_time::milliseconds (50));
// from code logic, we won't be fetching our own data
a1.set(p1 + "/0/0", data0);
BOOST_CHECK_EQUAL(a1.toString(), a2.toString());
- // BOOST_CHECK_EQUAL(a2.toString(), a3.toString());
+ BOOST_CHECK_EQUAL(a2.toString(), a3.toString());
// // single source, multiple data at once
- // string data1 = "Yes, give me that ketchup";
- // string data2 = "Don't look conspicuous, it draws fire";
+ string data1 = "Yes, give me that ketchup";
+ string data2 = "Don't look conspicuous, it draws fire";
- // s1.publish (p1, 0, data1, 10);
- // s1.publish(p1, 0, data2, 10);
- // sleep (1);
+ _LOG_DEBUG ("s1 publish");
+ s1.publish (p1, 0, data1, 10);
+ _LOG_DEBUG ("s1 publish");
+ s1.publish (p1, 0, data2, 10);
+ this_thread::sleep (posix_time::milliseconds (1000));
- // // from code logic, we won't be fetching our own data
+ // // // from code logic, we won't be fetching our own data
// a1.set(p1 + "/0/1", data1);
// a1.set(p1 + "/0/2", data2);
// BOOST_CHECK_EQUAL(a1.toString(), a2.toString());
- // BOOST_CHECK_EQUAL(a2.toString(), a3.toString());
+ // // BOOST_CHECK_EQUAL(a2.toString(), a3.toString());
// // another single source
- // string data3 = "You surf the Internet, I surf the real world";
+ // // string data3 = "You surf the Internet, I surf the real world";
// string data4 = "I got a fortune cookie once that said 'You like Chinese food'";
// string data5 = "Real men wear pink. Why? Because their wives make them";
- // s3.publish(p3, 0, data3, 10);
- // usleep(20000);
+ // // s3.publish(p3, 0, data3, 10);
+ // // this_thread::sleep (posix_time::milliseconds (1000));
+
// // another single source, multiple data at once
// s2.publish(p2, 0, data4, 10);
// s2.publish(p2, 0, data5, 10);
- // usleep(20000);
+ // this_thread::sleep (posix_time::milliseconds (1000));
// // from code logic, we won't be fetching our own data
- // a3.set(p3 + "/0/0", data3);
+ // // a3.set(p3 + "/0/0", data3);
// a2.set(p2 + "/0/0", data4);
// a2.set(p2 + "/0/1", data5);
// BOOST_CHECK_EQUAL(a1.toString(), a2.toString());
- // BOOST_CHECK_EQUAL(a2.toString(), a3.toString());
+ // // BOOST_CHECK_EQUAL(a2.toString(), a3.toString());
// // not sure weither this is simultanous data generation from multiple sources
// string data6 = "Shakespeare says: 'Prose before hos.'";
diff --git a/test/test_sync_logic.cc b/test/test_sync_logic.cc
index 66ea97a..f0abf82 100644
--- a/test/test_sync_logic.cc
+++ b/test/test_sync_logic.cc
@@ -48,16 +48,16 @@
{
m_map[p] = seq.getSeq ();
- cout << instance << "\t";
- if (!oldSeq.isValid ())
- cout << "Inserted: " << p << " (" << seq << ")" << endl;
- else
- cout << "Updated: " << p << " ( " << oldSeq << ".." << seq << ")" << endl;
+ // cout << instance << "\t";
+ // if (!oldSeq.isValid ())
+ // cout << "Inserted: " << p << " (" << seq << ")" << endl;
+ // else
+ // cout << "Updated: " << p << " ( " << oldSeq << ".." << seq << ")" << endl;
}
void onRemove (const string &p/*prefix*/)
{
- cout << instance << "\tRemoved: " << p << endl;
+ // cout << instance << "\tRemoved: " << p << endl;
m_map.erase (p);
}
diff --git a/wscript b/wscript
index 61536d4..ba0a706 100644
--- a/wscript
+++ b/wscript
@@ -5,6 +5,7 @@
def options(opt):
opt.add_option('--no-debug',action='store_true',default=False,dest='no_debug',help='''Make an optimized build of the library (remove debugging code)''')
+ opt.add_option('--log4cxx',action='store_true',default=False,dest='log4cxx',help='''Compile with log4cxx support''')
opt.load('compiler_c')
opt.load('compiler_cxx')
opt.load('boost')
@@ -37,20 +38,26 @@
conf.define ('STANDALONE', 1)
if not conf.options.no_debug:
conf.define ('_DEBUG', 1)
-
+
+ if conf.options.log4cxx:
+ conf.check_cfg(package='liblog4cxx', args=['--cflags', '--libs'], uselib_store='LOG4CXX', mandatory=True)
+
def build (bld):
- bld.shlib (target=APPNAME,
- features=['cxx', 'cxxshlib'],
- source = bld.path.ant_glob(['model/sync-*.cc',
- 'helper/sync-*.cc']),
- uselib = 'BOOST BOOST_IOSTREAMS BOOST_THREAD SSL TINYXML CCNX'
- )
+ libsync = bld.shlib (target=APPNAME,
+ features=['cxx', 'cxxshlib'],
+ source = bld.path.ant_glob(['model/sync-*.cc',
+ 'helper/sync-*.cc']),
+ use = 'BOOST BOOST_IOSTREAMS BOOST_THREAD SSL TINYXML CCNX')
# Unit tests
- bld.program (target="unit-tests",
- source = bld.path.ant_glob(['test/**/*.cc']),
- features=['cxx', 'cxxprogram'],
- use = 'BOOST_TEST sync')
+ unittests = bld.program (target="unit-tests",
+ source = bld.path.ant_glob(['test/**/*.cc']),
+ features=['cxx', 'cxxprogram'],
+ use = 'BOOST_TEST sync')
+
+ if bld.get_define ("HAVE_LOG4CXX"):
+ libsync.use += ' LOG4CXX'
+ unittests.use += ' LOG4CXX'
# doxygen docs
from waflib.Build import BuildContext