Introduce TX logging API

This patch introduces a new API for logging transactions from
tx-aware app layer protocols. It runs all the registered loggers
from a single thread module. This thread module takes care of the
transaction handling and flow locking. The logger just gets a
transaction to log out.

All loggers for a protocol will be run at the same time, so there
will not be any timing differences.

Loggers will no longer act as Thread Modules in the strictest sense.
The Func is NULL, and SetupOuputs no longer attaches them to the
thread module chain individually. Instead, after registering through
OutputRegisterTxModule, the setup data is used in the single logging
module.

The logger (LogFunc) is called for each transaction once, at the end
of the transaction.

src/Makefile.am

@@ -215,6 +215,7 @@ log-pcap.c log-pcap.h \
 log-tlslog.c log-tlslog.h \
 output.c output.h \
 output-packet.c output-packet.h \
+output-tx.c output-tx.h \
 packet-queue.c packet-queue.h \
 pkt-var.c pkt-var.h \
 reputation.c reputation.h \

src/output-tx.c

@@ -0,0 +1,278 @@
+/* Copyright (C) 2007-2013 Open Information Security Foundation
+ *
+ * You can copy, redistribute or modify this Program 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
+ * version 2 along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
+ * 02110-1301, USA.
+ */
+
+/**
+ * \file
+ *
+ * \author Victor Julien <victor@inliniac.net>
+ *
+ * AppLayer TX Logger Output registration functions
+ */
+
+#include "suricata-common.h"
+#include "tm-modules.h"
+#include "output-tx.h"
+#include "app-layer.h"
+#include "app-layer-parser.h"
+
+typedef struct OutputLoggerThreadStore_ {
+    void *thread_data;
+    struct OutputLoggerThreadStore_ *next;
+} OutputLoggerThreadStore;
+
+/** per thread data for this module, contains a list of per thread
+ *  data for the packet loggers. */
+typedef struct OutputLoggerThreadData_ {
+    OutputLoggerThreadStore *store;
+} OutputLoggerThreadData;
+
+/* logger instance, a module + a output ctx,
+ * it's perfectly valid that have multiple instances of the same
+ * log module (e.g. http.log) with different output ctx'. */
+typedef struct OutputTxLogger_ {
+    uint16_t alproto;
+    TxLogger LogFunc;
+    OutputCtx *output_ctx;
+    struct OutputTxLogger_ *next;
+    const char *name;
+} OutputTxLogger;
+
+static OutputTxLogger *list = NULL;
+
+int OutputRegisterTxLogger(char *name, uint16_t alproto, TxLogger LogFunc, OutputCtx *output_ctx) {
+    OutputTxLogger *op = SCMalloc(sizeof(*op));
+    if (op == NULL)
+        return -1;
+    memset(op, 0x00, sizeof(*op));
+
+    op->alproto = alproto;
+    op->LogFunc = LogFunc;
+    op->output_ctx = output_ctx;
+    op->name = SCStrdup(name);
+    if (op->name == NULL) {
+        SCFree(op);
+        return -1;
+    }
+
+    if (list == NULL)
+        list = op;
+    else {
+        OutputTxLogger *t = list;
+        while (t->next)
+            t = t->next;
+        t->next = op;
+    }
+
+    SCLogDebug("OutputRegisterTxLogger happy");
+    return 0;
+}
+
+static TmEcode OutputTxLog(ThreadVars *tv, Packet *p, void *thread_data, PacketQueue *pq, PacketQueue *postpq) {
+    BUG_ON(thread_data == NULL);
+    BUG_ON(list == NULL);
+
+    OutputLoggerThreadData *op_thread_data = (OutputLoggerThreadData *)thread_data;
+    OutputTxLogger *logger = list;
+    OutputLoggerThreadStore *store = op_thread_data->store;
+
+    BUG_ON(logger == NULL && store != NULL);
+    BUG_ON(logger != NULL && store == NULL);
+    BUG_ON(logger == NULL && store == NULL);
+
+    if (p->flow == NULL)
+        return TM_ECODE_OK;
+
+    Flow * const f = p->flow;
+
+    FLOWLOCK_WRLOCK(f); /* WRITE lock before we updated flow logged id */
+    AppProto alproto = f->alproto;//AppLayerGetProtoFromPacket(p);
+
+    if (AppLayerParserProtocolIsTxAware(p->proto, alproto) == 0)
+        goto end;
+
+    void *alstate = f->alstate;//AppLayerGetProtoStateFromPacket((const Packet *)p);
+    if (alstate == NULL) {
+        SCLogDebug("no alstate");
+        goto end;
+    }
+
+    uint64_t total_txs = AppLayerParserGetTxCnt(p->proto, alproto, alstate);
+    uint64_t tx_id = AppLayerParserGetTransactionLogId(f->alparser);
+    int tx_progress_done_value_ts =
+        AppLayerParserGetStateProgressCompletionStatus(p->proto, alproto, 0);
+    int tx_progress_done_value_tc =
+        AppLayerParserGetStateProgressCompletionStatus(p->proto, alproto, 1);
+    int proto_logged = 0;
+
+    for (; tx_id < total_txs; tx_id++)
+    {
+        void *tx = AppLayerParserGetTx(p->proto, alproto, alstate, tx_id);
+        if (tx == NULL) {
+            SCLogDebug("tx is NULL not logging");
+            continue;
+        }
+
+        if (!(AppLayerParserStateIssetFlag(f->alparser, APP_LAYER_PARSER_EOF)))
+        {
+            int tx_progress = AppLayerParserGetStateProgress(p->proto, alproto, tx, 0);
+            if (tx_progress < tx_progress_done_value_ts) {
+                SCLogDebug("progress not far enough, not logging");
+                break;
+            }
+
+            tx_progress = AppLayerParserGetStateProgress(p->proto, alproto, tx, 1);
+            if (tx_progress < tx_progress_done_value_tc) {
+                SCLogDebug("progress not far enough, not logging");
+                break;
+            }
+        }
+
+        // call each logger here (pseudo code)
+        logger = list;
+        store = op_thread_data->store;
+        while (logger && store) {
+            BUG_ON(logger->LogFunc == NULL);
+
+            SCLogDebug("logger %p", logger);
+            if (logger->alproto == alproto) {
+                SCLogDebug("alproto match, logging tx_id %ju", tx_id);
+                logger->LogFunc(tv, store->thread_data, p, f, alstate, tx, tx_id);
+                proto_logged = 1;
+            }
+
+            logger = logger->next;
+            store = store->next;
+
+            BUG_ON(logger == NULL && store != NULL);
+            BUG_ON(logger != NULL && store == NULL);
+        }
+
+        if (proto_logged) {
+            SCLogDebug("updating log tx_id %ju", tx_id);
+            AppLayerParserSetTransactionLogId(f->alparser);
+        }
+    }
+
+end:
+    FLOWLOCK_UNLOCK(f);
+    return TM_ECODE_OK;
+}
+
+/** \brief thread init for the tx logger
+ *  This will run the thread init functions for the individual registered
+ *  loggers */
+static TmEcode OutputTxLogThreadInit(ThreadVars *tv, void *initdata, void **data) {
+    OutputLoggerThreadData *td = SCMalloc(sizeof(*td));
+    if (td == NULL)
+        return TM_ECODE_FAILED;
+    memset(td, 0x00, sizeof(*td));
+
+    *data = (void *)td;
+
+    SCLogDebug("OutputTxLogThreadInit happy (*data %p)", *data);
+
+    OutputTxLogger *logger = list;
+    while (logger) {
+        TmModule *tm_module = TmModuleGetByName((char *)logger->name);
+        if (tm_module == NULL) {
+            SCLogError(SC_ERR_INVALID_ARGUMENT,
+                    "TmModuleGetByName for %s failed", logger->name);
+            exit(EXIT_FAILURE);
+        }
+
+        if (tm_module->ThreadInit) {
+            void *retptr = NULL;
+            if (tm_module->ThreadInit(tv, (void *)logger->output_ctx, &retptr) == TM_ECODE_OK) {
+                OutputLoggerThreadStore *ts = SCMalloc(sizeof(*ts));
+/* todo */      BUG_ON(ts == NULL);
+                memset(ts, 0x00, sizeof(*ts));
+
+                /* store thread handle */
+                ts->thread_data = retptr;
+
+                if (td->store == NULL) {
+                    td->store = ts;
+                } else {
+                    OutputLoggerThreadStore *tmp = td->store;
+                    while (tmp->next != NULL)
+                        tmp = tmp->next;
+                    tmp->next = ts;
+                }
+
+                SCLogDebug("%s is now set up", logger->name);
+            }
+        }
+
+        logger = logger->next;
+    }
+
+    return TM_ECODE_OK;
+}
+
+static TmEcode OutputTxLogThreadDeinit(ThreadVars *tv, void *thread_data) {
+    OutputLoggerThreadData *op_thread_data = (OutputLoggerThreadData *)thread_data;
+    OutputLoggerThreadStore *store = op_thread_data->store;
+    OutputTxLogger *logger = list;
+
+    while (logger && store) {
+        TmModule *tm_module = TmModuleGetByName((char *)logger->name);
+        if (tm_module == NULL) {
+            SCLogError(SC_ERR_INVALID_ARGUMENT,
+                    "TmModuleGetByName for %s failed", logger->name);
+            exit(EXIT_FAILURE);
+        }
+
+        if (tm_module->ThreadDeinit) {
+            tm_module->ThreadDeinit(tv, store->thread_data);
+        }
+
+        logger = logger->next;
+        store = store->next;
+    }
+    return TM_ECODE_OK;
+}
+
+static void OutputTxLogExitPrintStats(ThreadVars *tv, void *thread_data) {
+    OutputLoggerThreadData *op_thread_data = (OutputLoggerThreadData *)thread_data;
+    OutputLoggerThreadStore *store = op_thread_data->store;
+    OutputTxLogger *logger = list;
+
+    while (logger && store) {
+        TmModule *tm_module = TmModuleGetByName((char *)logger->name);
+        if (tm_module == NULL) {
+            SCLogError(SC_ERR_INVALID_ARGUMENT,
+                    "TmModuleGetByName for %s failed", logger->name);
+            exit(EXIT_FAILURE);
+        }
+
+        if (tm_module->ThreadExitPrintStats) {
+            tm_module->ThreadExitPrintStats(tv, store->thread_data);
+        }
+
+        logger = logger->next;
+        store = store->next;
+    }
+}
+
+void TmModuleTxLoggerRegister (void) {
+    tmm_modules[TMM_TXLOGGER].name = "__tx_logger__";
+    tmm_modules[TMM_TXLOGGER].ThreadInit = OutputTxLogThreadInit;
+    tmm_modules[TMM_TXLOGGER].Func = OutputTxLog;
+    tmm_modules[TMM_TXLOGGER].ThreadExitPrintStats = OutputTxLogExitPrintStats;
+    tmm_modules[TMM_TXLOGGER].ThreadDeinit = OutputTxLogThreadDeinit;
+    tmm_modules[TMM_TXLOGGER].cap_flags = 0;
+}

src/output-tx.h

@@ -0,0 +1,43 @@
+/* Copyright (C) 2007-2013 Open Information Security Foundation
+ *
+ * You can copy, redistribute or modify this Program 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
+ * version 2 along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
+ * 02110-1301, USA.
+ */
+
+/**
+ * \file
+ *
+ * \author Victor Julien <victor@inliniac.net>
+ *
+ * AppLayer TX Logger Output registration functions
+ */
+
+#ifndef __OUTPUT_TX_H__
+#define __OUTPUT_TX_H__
+
+#include "decode.h"
+
+/** packet logger function pointer type */
+typedef int (*TxLogger)(ThreadVars *, void *thread_data, const Packet *, Flow *f, void *state, void *tx, uint64_t tx_id);
+
+/** packet logger condition function pointer type,
+ *  must return true for packets that should be logged
+ */
+//typedef int (*TxLogCondition)(ThreadVars *, const Packet *);
+
+int OutputRegisterTxLogger(char *name, uint16_t alproto, TxLogger LogFunc, OutputCtx *);
+
+void TmModuleTxLoggerRegister (void);
+
+#endif /* __OUTPUT_PACKET_H__ */

src/output.c

@@ -108,6 +108,46 @@ error:
     exit(EXIT_FAILURE);
 }
 
+/**
+ * \brief Register a tx output module.
+ *
+ * This function will register an output module so it can be
+ * configured with the configuration file.
+ *
+ * \retval Returns 0 on success, -1 on failure.
+ */
+void
+OutputRegisterTxModule(char *name, char *conf_name,
+    OutputCtx *(*InitFunc)(ConfNode *), uint16_t alproto,
+    TxLogger TxLogFunc)
+{
+    if (unlikely(TxLogFunc == NULL)) {
+        goto error;
+    }
+
+    OutputModule *module = SCCalloc(1, sizeof(*module));
+    if (unlikely(module == NULL)) {
+        goto error;
+    }
+
+    module->name = SCStrdup(name);
+    if (unlikely(module->name == NULL))
+        goto error;
+    module->conf_name = SCStrdup(conf_name);
+    if (unlikely(module->conf_name == NULL))
+        goto error;
+    module->InitFunc = InitFunc;
+    module->TxLogFunc = TxLogFunc;
+    module->alproto = alproto;
+    TAILQ_INSERT_TAIL(&output_modules, module, entries);
+
+    SCLogDebug("Tx logger \"%s\" registered.", name);
+    return;
+error:
+    SCLogError(SC_ERR_FATAL, "Fatal error encountered. Exiting...");
+    exit(EXIT_FAILURE);
+}
+
 /**
  * \brief Get an output module by name.
  *

src/output.h

@@ -31,6 +31,7 @@
 #define DEFAULT_LOG_FILETYPE        "regular"
 
 #include "output-packet.h"
+#include "output-tx.h"
 
 typedef struct OutputModule_ {
     char *name;
@@ -39,6 +40,8 @@ typedef struct OutputModule_ {
 
     PacketLogger PacketLogFunc;
     PacketLogCondition PacketConditionFunc;
+    TxLogger TxLogFunc;
+    uint16_t alproto;
 
     TAILQ_ENTRY(OutputModule_) entries;
 } OutputModule;
@@ -48,6 +51,11 @@ void OutputRegisterModule(char *, char *, OutputCtx *(*)(ConfNode *));
 void OutputRegisterPacketModule(char *name, char *conf_name,
     OutputCtx *(*InitFunc)(ConfNode *),
     PacketLogger LogFunc, PacketLogCondition ConditionFunc);
+void
+OutputRegisterTxModule(char *name, char *conf_name,
+    OutputCtx *(*InitFunc)(ConfNode *), uint16_t alproto,
+    TxLogger TxLogFunc);
+
 
 OutputModule *OutputGetModuleByConfName(char *name);
 void OutputDeregisterAll(void);

src/runmodes.c

@@ -424,6 +424,7 @@ void RunModeInitializeOutputs(void)
     ConfNode *output, *output_config;
     TmModule *tm_module;
     TmModule *pkt_logger_module = NULL;
+    TmModule *tx_logger_module = NULL;
     const char *enabled;
 
     TAILQ_FOREACH(output, &outputs->head, next) {
@@ -507,7 +508,28 @@ void RunModeInitializeOutputs(void)
                 TAILQ_INSERT_TAIL(&RunModeOutputs, runmode_output, entries);
                 SCLogDebug("__packet_logger__ added");
             }
+        } else if (module->TxLogFunc) {
+            SCLogDebug("%s is a tx logger", module->name);
+            OutputRegisterTxLogger(module->name, module->alproto,
+                    module->TxLogFunc, output_ctx);
+
+            /* need one instance of the tx logger module */
+            if (tx_logger_module == NULL) {
+                tx_logger_module = TmModuleGetByName("__tx_logger__");
+                if (tx_logger_module == NULL) {
+                    SCLogError(SC_ERR_INVALID_ARGUMENT,
+                            "TmModuleGetByName for __tx_logger__ failed");
+                    exit(EXIT_FAILURE);
+                }
 
+                RunModeOutput *runmode_output = SCCalloc(1, sizeof(RunModeOutput));
+                if (unlikely(runmode_output == NULL))
+                    return;
+                runmode_output->tm_module = tx_logger_module;
+                runmode_output->output_ctx = NULL;
+                TAILQ_INSERT_TAIL(&RunModeOutputs, runmode_output, entries);
+                SCLogDebug("__tx_logger__ added");
+            }
         } else {
             SCLogDebug("%s is a regular logger", module->name);
 

src/suricata.c

@@ -152,6 +152,7 @@
 
 #include "output.h"
 #include "output-packet.h"
+#include "output-tx.h"
 #include "util-privs.h"
 
 #include "tmqh-packetpool.h"
@@ -804,6 +805,7 @@ void RegisterAllModules()
     /* dns log */
     TmModuleLogDnsLogRegister();
     TmModulePacketLoggerRegister();
+    TmModuleTxLoggerRegister();
     TmModuleDebugList();
 
 }

src/tm-threads-common.h

@@ -80,6 +80,7 @@ typedef enum {
     TMM_RECEIVENAPATECH,
     TMM_DECODENAPATECH,
     TMM_PACKETLOGGER,
+    TMM_TXLOGGER,
     TMM_SIZE,
 } TmmId;