Skip to content

Commit

Permalink
Enhancements to droplog - part 1
Browse files Browse the repository at this point in the history 
1. Print src and dst mac as separate fields
2. Separate log file for drop_logs.
   Configure droplog destination with command line arguments
   --drop_log <file-name> --drop_log_syslog (in case sink is
   syslog)
   By default droplogs go to the opflex-agent log file.

Signed-off-by: Kiran Shastri <shastrinator@gmail.com>
(cherry picked from commit 404f401)
  • Loading branch information
@shastrinator
shastrinator committed Jan 22, 2023
1 parent 130b89b commit 27e8d8a
Show file tree
Hide file tree
Showing 6 changed files with 97 additions and 18 deletions.
12 changes: 10 additions & 2 deletions agent-ovs/cmd/opflex_agent.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -221,10 +221,13 @@ int main(int argc, char** argv) {
("watch,w", "Watch configuration directories for changes")
("log", po::value<string>()->default_value(""),
"Log to the specified file (default standard out)")
("drop_log", po::value<string>()->default_value(""),
"Log drops to the specified file (default standard out)")
("level", po::value<string>()->default_value("info"),
"Use the specified log level (default info). "
"Overridden by log level in configuration file")
("syslog", "Log to syslog instead of file or standard out")
("drop_log_syslog", "Log drops to syslog instead of file or standard out")
("daemon", "Run the agent as a daemon");
} catch (const boost::bad_lexical_cast& e) {
std::cerr << e.what() << std::endl;
Expand All @@ -233,8 +236,8 @@ int main(int argc, char** argv) {

bool daemon = false;
bool watch = false;
bool logToSyslog = false;
std::string log_file;
bool logToSyslog = false,dropLogSyslog = false;
std::string log_file, dropLogFile;
std::string level_str;

po::variables_map vm;
Expand All @@ -260,7 +263,11 @@ int main(int argc, char** argv) {
watch = true;
}
log_file = vm["log"].as<string>();
dropLogFile = vm["drop_log"].as<string>();
level_str = vm["level"].as<string>();
if (vm.count("drop_log_syslog")) {
dropLogSyslog = true;
}
if (vm.count("syslog")) {
logToSyslog = true;
}
Expand All @@ -273,6 +280,7 @@ int main(int argc, char** argv) {
daemonize();

initLogging(level_str, logToSyslog, log_file);
initDropLogging(dropLogSyslog, dropLogFile);

// Initialize agent and configuration
std::vector<string> configFiles;
Expand Down
31 changes: 31 additions & 0 deletions agent-ovs/lib/include/opflexagent/logging.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -60,6 +60,27 @@ void initLogging(const std::string& level, bool toSyslog,
const std::string& log_file,
const std::string& syslog_name = "opflex-agent");

/**
* Initialize droplogging
*
* @param toSyslog if true, log messages are written to syslog; parameter
* "log_file" is ignored in that case
* @param log_file the file to log to, or empty for console
* @param level the log level to log at
* @param syslog_name the name to use when logging to syslog
*/
void initDropLogging(bool toSyslog,
const std::string &log_file,
const std::string& level="info",
const std::string& syslog_name = "opflex-agent-drop-log");

/**
* Check whether droplogs are to be managed or as opflex-agent logs
* True means that they are treated as opflex-agent logs.
* False means they go to a separate file/syslog as configured
*/
bool isDropLogConsoleSink();

/**
* Change the logging level of the agent.
*
Expand All @@ -81,6 +102,12 @@ const std::string & getLogLevelString();
*/
LogSink * getLogSink();

/**
* Get the currently configured drop-log destination. The return pointer is never
* NULL.
*/
LogSink * getDropLogSink();

/**
* Logger used to construct and write a log message to the current log
* destination.
Expand Down Expand Up @@ -141,6 +168,10 @@ class Logger {
if (lvl <= opflexagent::logLevel) \
opflexagent::getLogSink()->write(lvl, filename, lineNo, \
functionName, message);

#define DROPLOG(message) \
opflexagent::getDropLogSink()->write(LogLevel::INFO,"",-1,"", \
message);
} /* namespace opflexagent */

#endif /* AGENT_LOGGING_H */
47 changes: 41 additions & 6 deletions agent-ovs/lib/logging.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@

#include <fstream>
#include <mutex>
#include <atomic>

#include <syslog.h>

Expand All @@ -29,6 +30,7 @@ using opflex::logging::OFLogHandler;
namespace opflexagent {

AgentLogHandler logHandler(OFLogHandler::NO_LOGGING);
AgentLogHandler dropLogHandler(OFLogHandler::NO_LOGGING);

LogLevel logLevel = DEBUG;

Expand Down Expand Up @@ -75,9 +77,14 @@ class OStreamLogSink : public LogSink {
case FATAL: levelStr = LEVEL_STR_FATAL; break;
}
std::lock_guard<std::mutex> lock(logMtx);
(*out) << "[" << boost::posix_time::microsec_clock::local_time()
<< "] [" << levelStr << "] [" << filename << ":" << lineno << ":"
<< functionName << "] " << message << std::endl;
if( lineno != -1) {
(*out) << "[" << boost::posix_time::microsec_clock::local_time()
<< "] [" << levelStr << "] [" << filename << ":" << lineno << ":"
<< functionName << "] " << message << std::endl;
} else {
(*out) << "[" << boost::posix_time::microsec_clock::local_time()
<< "] " << message << std::endl;
}
}

private:
Expand Down Expand Up @@ -123,9 +130,13 @@ class SyslogLogSink : public LogSink {
case ERROR: priority = LOG_ERR; break;
case FATAL: priority = LOG_CRIT; break;
}
syslog(priority,
"[%s:%d:%s] %s",
filename, lineno, functionName, message.c_str());
if(lineno != -1) {
syslog(priority,
"[%s:%d:%s] %s",
filename, lineno, functionName, message.c_str());
} else {
syslog(priority," %s",message.c_str());
}
}

private:
Expand All @@ -134,11 +145,21 @@ class SyslogLogSink : public LogSink {

static OStreamLogSink consoleLogSink(std::cout);
static LogSink * currentLogSink = &consoleLogSink;
static LogSink * currentDropLogSink = &consoleLogSink;
static std::atomic<bool> dropLogConsoleSink;

LogSink * getLogSink() {
return currentLogSink;
}

LogSink * getDropLogSink() {
return currentDropLogSink;
}

bool isDropLogConsoleSink() {
return dropLogConsoleSink;
}

void initLogging(const std::string& levelstr,
bool toSyslog,
const std::string& log_file,
Expand All @@ -153,6 +174,20 @@ void initLogging(const std::string& levelstr,
setLoggingLevel(levelstr);
}

void initDropLogging(bool toSyslog,
const std::string& log_file,
const std::string &levelstr,
const std::string& syslog_name) {
if (toSyslog) {
currentDropLogSink = new SyslogLogSink(syslog_name);
} else if (!log_file.empty()) {
currentDropLogSink = new OStreamLogSink(log_file);
} else {
dropLogConsoleSink = true;
}
setLoggingLevel(levelstr);
}

void setLoggingLevel(const std::string& newLevelstr) {
OFLogHandler::Level level = OFLogHandler::INFO;

Expand Down
2 changes: 1 addition & 1 deletion agent-ovs/ovs/PacketDecoderLayers.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,7 @@ int EthernetLayer::configure() {

void EthernetLayer::getFormatString(boost::format &fmtStr) {
//Format string to print the layer goes here
fmtStr = boost::format(" MAC=%1%:%2%:%3%");
fmtStr = boost::format(" SMAC=%2% DMAC=%1% ETYP=%3%");
}

int QtagLayer::configure() {
Expand Down
9 changes: 7 additions & 2 deletions agent-ovs/ovs/PacketLogHandler.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -252,10 +252,15 @@ void PacketLogHandler::parseLog(unsigned char *buf , std::size_t length) {
pruneLog(p);
if(p.pruneLog)
return;
std::string dropReason;
std::string dropReason,dropLogMsg;
bool isPermit = getDropReason(p, dropReason);
p.packetTuple.setField(0, dropReason);
LOG(INFO)<< dropReason << " " << p.parsedString;
dropLogMsg = dropReason + " " + p.parsedString;
if(!opflexagent::isDropLogConsoleSink()) {
DROPLOG(dropLogMsg);
} else {
LOG(INFO)<< dropLogMsg;
}
if(!packetEventNotifSock.empty() && !isPermit )
{
{
Expand Down
14 changes: 7 additions & 7 deletions agent-ovs/ovs/test/PacketDecoder_test.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -168,7 +168,7 @@ BOOST_FIXTURE_TEST_CASE(arp_test, PacketDecoderFixture) {
auto pktDecoder = pktLogger.getDecoder();
ParseInfo p(&pktDecoder);
PacketTuple expectedTuple("", "Int-PORT_SECURITY_TABLE DENY", "9e:72:a6:94:18:af", "ff:ff:ff:ff:ff:ff", "ARP", "13.0.0.3", "13.0.0.5" ,"", "", "");
std::string expected(" MAC=ff:ff:ff:ff:ff:ff:9e:72:a6:94:18:af:ARP ARP_SPA=13.0.0.3 ARP_TPA=13.0.0.5 ARP_OP=1");
std::string expected(" SMAC=9e:72:a6:94:18:af DMAC=ff:ff:ff:ff:ff:ff ETYP=ARP ARP_SPA=13.0.0.3 ARP_TPA=13.0.0.5 ARP_OP=1");
int ret = pktDecoder.decode(arp_buf, 74, p);
BOOST_CHECK(ret == 0);
std::string dropReason;
Expand All @@ -182,7 +182,7 @@ BOOST_FIXTURE_TEST_CASE(icmp_test, PacketDecoderFixture) {
auto pktDecoder = pktLogger.getDecoder();
ParseInfo p(&pktDecoder);
PacketTuple expectedTuple("", "Acc-GROUP_MAP_TABLE MISS", "9e:72:a6:94:18:af", "5a:08:66:ce:0b:49", "IPv4", "14.0.0.2", "100.0.0.1" ,"ICMP", "", "");
std::string expected(" MAC=5a:08:66:ce:0b:49:9e:72:a6:94:18:af:IPv4 SRC=14.0.0.2 DST=100.0.0.1 LEN=28 DSCP=0 TTL=255 ID=0 FLAGS=0 FRAG=0 PROTO=ICMP TYPE=8 CODE=0 ID=0 SEQ=0");
std::string expected(" SMAC=9e:72:a6:94:18:af DMAC=5a:08:66:ce:0b:49 ETYP=IPv4 SRC=14.0.0.2 DST=100.0.0.1 LEN=28 DSCP=0 TTL=255 ID=0 FLAGS=0 FRAG=0 PROTO=ICMP TYPE=8 CODE=0 ID=0 SEQ=0");
int ret = pktDecoder.decode(icmp_buf, 74, p);
BOOST_CHECK(ret == 0);
std::string dropReason;
Expand All @@ -196,7 +196,7 @@ BOOST_FIXTURE_TEST_CASE(tcp_test, PacketDecoderFixture) {
auto pktDecoder = pktLogger.getDecoder();
ParseInfo p(&pktDecoder);
PacketTuple expectedTuple("", "Int-SOURCE_TABLE PERMIT", "9e:72:a6:94:18:af", "5a:08:66:ce:0b:49", "IPv4", "14.0.0.2", "100.0.0.1" ,"TCP", "41634", "179");
std::string expected(" MAC=5a:08:66:ce:0b:49:9e:72:a6:94:18:af:IPv4 SRC=14.0.0.2 DST=100.0.0.1 LEN=28 DSCP=0 TTL=255 ID=0 FLAGS=0 FRAG=0 PROTO=TCP SPT=41634 DPT=179 SEQ=2939917199 ACK=0 LEN=10 WINDOWS=29200 SYN URGP=0");
std::string expected(" SMAC=9e:72:a6:94:18:af DMAC=5a:08:66:ce:0b:49 ETYP=IPv4 SRC=14.0.0.2 DST=100.0.0.1 LEN=28 DSCP=0 TTL=255 ID=0 FLAGS=0 FRAG=0 PROTO=TCP SPT=41634 DPT=179 SEQ=2939917199 ACK=0 LEN=10 WINDOWS=29200 SYN URGP=0");
int ret = pktDecoder.decode(tcp_buf, 106, p);
BOOST_CHECK(ret == 0);
std::string dropReason;
Expand All @@ -210,7 +210,7 @@ BOOST_FIXTURE_TEST_CASE(udp_test, PacketDecoderFixture) {
auto pktDecoder = pktLogger.getDecoder();
ParseInfo p(&pktDecoder);
PacketTuple expectedTuple("", "Acc-SEC_GROUP_OUT_TABLE MISS", "9e:72:a6:94:18:af", "5a:08:66:ce:0b:49", "IPv4", "14.0.0.2", "100.0.0.1" ,"UDP", "60376", "161");
std::string expected(" MAC=5a:08:66:ce:0b:49:9e:72:a6:94:18:af:IPv4 SRC=14.0.0.2 DST=100.0.0.1 LEN=28 DSCP=0 TTL=255 ID=0 FLAGS=0 FRAG=0 PROTO=UDP SPT=60376 DPT=161 LEN=74");
std::string expected(" SMAC=9e:72:a6:94:18:af DMAC=5a:08:66:ce:0b:49 ETYP=IPv4 SRC=14.0.0.2 DST=100.0.0.1 LEN=28 DSCP=0 TTL=255 ID=0 FLAGS=0 FRAG=0 PROTO=UDP SPT=60376 DPT=161 LEN=74");
int ret = pktDecoder.decode(udp_buf, 66, p);
BOOST_CHECK(ret == 0);
std::string dropReason;
Expand All @@ -224,7 +224,7 @@ BOOST_FIXTURE_TEST_CASE(udp_over_v6_test, PacketDecoderFixture) {
auto pktDecoder = pktLogger.getDecoder();
ParseInfo p(&pktDecoder);
PacketTuple expectedTuple("", "Int-SERVICE_REV_TABLE MISS", "9e:72:a6:94:18:af", "5a:08:66:ce:0b:49", "IPv6", "fe80::a00:27ff:fefe:8f95", "ff02::1:2" ,"UDP", "546", "547");
std::string expected(" MAC=5a:08:66:ce:0b:49:9e:72:a6:94:18:af:IPv6 SRC=fe80::a00:27ff:fefe:8f95 DST=ff02::1:2 LEN=60 TC=0 HL=1 FL=0 PROTO=UDP SPT=546 DPT=547 LEN=60");
std::string expected(" SMAC=9e:72:a6:94:18:af DMAC=5a:08:66:ce:0b:49 ETYP=IPv6 SRC=fe80::a00:27ff:fefe:8f95 DST=ff02::1:2 LEN=60 TC=0 HL=1 FL=0 PROTO=UDP SPT=546 DPT=547 LEN=60");
int ret = pktDecoder.decode(udpv6_buf, 86, p);
BOOST_CHECK(ret == 0);
std::string dropReason;
Expand All @@ -238,7 +238,7 @@ BOOST_FIXTURE_TEST_CASE(tcp_over_v6_test, PacketDecoderFixture) {
auto pktDecoder = pktLogger.getDecoder();
ParseInfo p(&pktDecoder);
PacketTuple expectedTuple("", "Int-BRIDGE_TABLE MISS", "9e:72:a6:94:18:af", "5a:08:66:ce:0b:49", "IPv6", "fe80::a00:27ff:fefe:8f95", "ff02::1:2" ,"TCP", "41634", "179");
std::string expected(" MAC=5a:08:66:ce:0b:49:9e:72:a6:94:18:af:IPv6 SRC=fe80::a00:27ff:fefe:8f95 DST=ff02::1:2 LEN=60 TC=0 HL=1 FL=0 PROTO=TCP SPT=41634 DPT=179 SEQ=2939917199 ACK=0 LEN=10 WINDOWS=29200 SYN URGP=0");
std::string expected(" SMAC=9e:72:a6:94:18:af DMAC=5a:08:66:ce:0b:49 ETYP=IPv6 SRC=fe80::a00:27ff:fefe:8f95 DST=ff02::1:2 LEN=60 TC=0 HL=1 FL=0 PROTO=TCP SPT=41634 DPT=179 SEQ=2939917199 ACK=0 LEN=10 WINDOWS=29200 SYN URGP=0");
int ret = pktDecoder.decode(tcpv6_buf, 118, p);
BOOST_CHECK(ret == 0);
std::string dropReason;
Expand All @@ -252,7 +252,7 @@ BOOST_FIXTURE_TEST_CASE(ip_options_unrecognized_test, PacketDecoderFixture) {
auto pktDecoder = pktLogger.getDecoder();
ParseInfo p(&pktDecoder);
PacketTuple expectedTuple("", "Int-PORT_SECURITY_TABLE MISS", "fa:16:3e:d3:f3:0b", "01:00:5e:00:00:16", "IPv4", "192.168.210.8", "224.0.0.22" ,"2_unrecognized", "", "");
std::string expected(" MAC=01:00:5e:00:00:16:fa:16:3e:d3:f3:0b:Qtag QTAG=4094 IPv4 SRC=192.168.210.8 DST=224.0.0.22 LEN=40 DSCP=48 TTL=1 ID=0 FLAGS=2 FRAG=0 PROTO=2_unrecognized");
std::string expected(" SMAC=fa:16:3e:d3:f3:0b DMAC=01:00:5e:00:00:16 ETYP=Qtag QTAG=4094 IPv4 SRC=192.168.210.8 DST=224.0.0.22 LEN=40 DSCP=48 TTL=1 ID=0 FLAGS=2 FRAG=0 PROTO=2_unrecognized");
int ret = pktDecoder.decode(igmp_buf, 178, p);
BOOST_CHECK(ret == 0);
std::string dropReason;
Expand Down

0 comments on commit 27e8d8a

Please sign in to comment.