tx logging: only update logged tx id if all loggers logged

Prevents the case where the logged id is incremented if a newer
transaction is complete and an older one is still outstanding.

For example, dns request0, unsolicited dns response, dns response0

would result in the valid response0 never being logged.

Similarily this could happen for:
  request0, request1, response1, response0

which would end up having request0, request1 and response1 logged,
but response0 would not be logged.

diff --git a/src/app-layer-parser.c b/src/app-layer-parser.c
index 6730e8144e97a5e9d1e6e5d20b3b3c2436451e1f..359bd9a076018a9ee0d6b387df03b136a0f43d8f 100644 (file)
--- a/src/app-layer-parser.c
+++ b/src/app-layer-parser.c
@@ -597,12 +597,12 @@ uint64_t AppLayerParserGetTransactionLogId(AppLayerParserState *pstate)
     SCReturnCT((pstate == NULL) ? 0 : pstate->log_id, "uint64_t");
 }
 
-void AppLayerParserSetTransactionLogId(AppLayerParserState *pstate)
+void AppLayerParserSetTransactionLogId(AppLayerParserState *pstate, uint64_t tx_id)
 {
     SCEnter();
 
     if (pstate != NULL)
-        pstate->log_id++;
+        pstate->log_id = tx_id;
 
     SCReturn;
 }

diff --git a/src/app-layer-parser.h b/src/app-layer-parser.h
index be4043032c0d295cc707f27c04c12b6b0e9e7b07..8e70d258fba93077e347f613468faf8a4415481e 100644 (file)
--- a/src/app-layer-parser.h
+++ b/src/app-layer-parser.h
@@ -162,7 +162,7 @@ void AppLayerParserDestroyProtocolParserLocalStorage(uint8_t ipproto, AppProto a
 
 
 uint64_t AppLayerParserGetTransactionLogId(AppLayerParserState *pstate);
-void AppLayerParserSetTransactionLogId(AppLayerParserState *pstate);
+void AppLayerParserSetTransactionLogId(AppLayerParserState *pstate, uint64_t tx_id);
 void AppLayerParserSetTxLogged(uint8_t ipproto, AppProto alproto, void *alstate,
                                void *tx, uint32_t logger);
 int AppLayerParserGetTxLogged(uint8_t ipproto, AppProto alproto, void *alstate,

diff --git a/src/output-tx.c b/src/output-tx.c
index aac57e524ca5c51bc7f53e06e74d8e9de3374620..482fa087d9adf4d7977426d554ff2876f3012074 100644 (file)
--- a/src/output-tx.c
+++ b/src/output-tx.c
@@ -163,10 +163,17 @@ static TmEcode OutputTxLog(ThreadVars *tv, Packet *p, void *thread_data)
 
     uint64_t total_txs = AppLayerParserGetTxCnt(p->proto, alproto, alstate);
     uint64_t tx_id = AppLayerParserGetTransactionLogId(f->alparser);
+    uint64_t max_id = tx_id;
+    int logged = 0;
+    int gap = 0;
 
     for (; tx_id < total_txs; tx_id++)
     {
-        int logger_not_logged = 0;
+        /* Track the number of loggers, of the eligible loggers that
+         * actually logged this transaction. They all must have logged
+         * before the transaction is considered logged. */
+        int number_of_loggers = 0;
+        int loggers_that_logged = 0;
 
         void *tx = AppLayerParserGetTx(p->proto, alproto, alstate, tx_id);
         if (tx == NULL) {
@@ -195,10 +202,12 @@ static TmEcode OutputTxLog(ThreadVars *tv, Packet *p, void *thread_data)
             if (logger->alproto == alproto) {
                 SCLogDebug("alproto match, logging tx_id %"PRIu64, tx_id);
 
+                number_of_loggers++;
+
                 if (AppLayerParserGetTxLogged(p->proto, alproto, alstate, tx,
                         logger->id)) {
                     SCLogDebug("logger has already logged this transaction");
-
+                    loggers_that_logged++;
                     goto next;
                 }
 
@@ -208,30 +217,30 @@ static TmEcode OutputTxLog(ThreadVars *tv, Packet *p, void *thread_data)
                         int r = logger->LogCondition(tv, p, alstate, tx, tx_id);
                         if (r == FALSE) {
                             SCLogDebug("conditions not met, not logging");
-                            logger_not_logged = 1;
                             goto next;
                         }
                     } else {
                         if (tx_progress_tc < logger->tc_log_progress) {
                             SCLogDebug("progress not far enough, not logging");
-                            logger_not_logged = 1;
                             goto next;
                         }
 
                         if (tx_progress_ts < logger->ts_log_progress) {
                             SCLogDebug("progress not far enough, not logging");
-                            logger_not_logged = 1;
                             goto next;
                         }
                     }
                 }
 
+                SCLogDebug("Logging tx_id %"PRIu64" to logger %d", tx_id,
+                    logger->logger_id);
                 PACKET_PROFILING_LOGGER_START(p, logger->logger_id);
                 logger->LogFunc(tv, store->thread_data, p, f, alstate, tx, tx_id);
                 PACKET_PROFILING_LOGGER_END(p, logger->logger_id);
 
                 AppLayerParserSetTxLogged(p->proto, alproto, alstate, tx,
                                           logger->id);
+                loggers_that_logged++;
             }
 
 next:
@@ -242,12 +251,27 @@ next:
             BUG_ON(logger != NULL && store == NULL);
         }
 
-        if (!logger_not_logged) {
-            SCLogDebug("updating log tx_id %"PRIu64, tx_id);
-            AppLayerParserSetTransactionLogId(f->alparser);
+        /* If all loggers logged set a flag and update the last tx_id
+         * that was logged.
+         *
+         * If not all loggers were logged we flag that there was a gap
+         * so any subsequent transactions in this loop don't increase
+         * the maximum ID that was logged. */
+        if (!gap && loggers_that_logged == number_of_loggers) {
+            logged = 1;
+            max_id = tx_id;
+        } else {
+            gap = 1;
         }
     }
 
+    /* Update the the last ID that has been logged with all
+     * transactions before it. */
+    if (logged) {
+        SCLogDebug("updating log tx_id %"PRIu64, max_id);
+        AppLayerParserSetTransactionLogId(f->alparser, max_id + 1);
+    }
+
 end:
     return TM_ECODE_OK;
 }