/src/suricata7/src/output-tx.c
Line | Count | Source |
1 | | /* Copyright (C) 2007-2022 Open Information Security Foundation |
2 | | * |
3 | | * You can copy, redistribute or modify this Program under the terms of |
4 | | * the GNU General Public License version 2 as published by the Free |
5 | | * Software Foundation. |
6 | | * |
7 | | * This program is distributed in the hope that it will be useful, |
8 | | * but WITHOUT ANY WARRANTY; without even the implied warranty of |
9 | | * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the |
10 | | * GNU General Public License for more details. |
11 | | * |
12 | | * You should have received a copy of the GNU General Public License |
13 | | * version 2 along with this program; if not, write to the Free Software |
14 | | * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA |
15 | | * 02110-1301, USA. |
16 | | */ |
17 | | |
18 | | /** |
19 | | * \file |
20 | | * |
21 | | * \author Victor Julien <victor@inliniac.net> |
22 | | * |
23 | | * AppLayer TX Logger Output registration functions |
24 | | */ |
25 | | |
26 | | #include "suricata-common.h" |
27 | | #include "output.h" |
28 | | #include "output-tx.h" |
29 | | #include "stream.h" |
30 | | #include "app-layer.h" |
31 | | #include "app-layer-parser.h" |
32 | | #include "util-profiling.h" |
33 | | #include "util-validate.h" |
34 | | |
35 | | /** per thread data for this module, contains a list of per thread |
36 | | * data for the packet loggers. */ |
37 | | typedef struct OutputTxLoggerThreadData_ { |
38 | | OutputLoggerThreadStore *store[ALPROTO_MAX]; |
39 | | |
40 | | /* thread local data from file api */ |
41 | | OutputFileLoggerThreadData *file; |
42 | | /* thread local data from filedata api */ |
43 | | OutputFiledataLoggerThreadData *filedata; |
44 | | } OutputTxLoggerThreadData; |
45 | | |
46 | | /* logger instance, a module + a output ctx, |
47 | | * it's perfectly valid that have multiple instances of the same |
48 | | * log module (e.g. http.log) with different output ctx'. */ |
49 | | typedef struct OutputTxLogger_ { |
50 | | AppProto alproto; |
51 | | TxLogger LogFunc; |
52 | | TxLoggerCondition LogCondition; |
53 | | OutputCtx *output_ctx; |
54 | | struct OutputTxLogger_ *next; |
55 | | const char *name; |
56 | | LoggerId logger_id; |
57 | | uint32_t id; |
58 | | int tc_log_progress; |
59 | | int ts_log_progress; |
60 | | TmEcode (*ThreadInit)(ThreadVars *, const void *, void **); |
61 | | TmEcode (*ThreadDeinit)(ThreadVars *, void *); |
62 | | void (*ThreadExitPrintStats)(ThreadVars *, void *); |
63 | | } OutputTxLogger; |
64 | | |
65 | | static OutputTxLogger *list[ALPROTO_MAX] = { NULL }; |
66 | | |
67 | | int OutputRegisterTxLogger(LoggerId id, const char *name, AppProto alproto, |
68 | | TxLogger LogFunc, |
69 | | OutputCtx *output_ctx, int tc_log_progress, |
70 | | int ts_log_progress, TxLoggerCondition LogCondition, |
71 | | ThreadInitFunc ThreadInit, |
72 | | ThreadDeinitFunc ThreadDeinit, |
73 | | void (*ThreadExitPrintStats)(ThreadVars *, void *)) |
74 | 46 | { |
75 | 46 | if (alproto != ALPROTO_UNKNOWN && !(AppLayerParserIsEnabled(alproto))) { |
76 | 0 | SCLogDebug( |
77 | 0 | "%s logger not enabled: protocol %s is disabled", name, AppProtoToString(alproto)); |
78 | 0 | return -1; |
79 | 0 | } |
80 | 46 | OutputTxLogger *op = SCMalloc(sizeof(*op)); |
81 | 46 | if (op == NULL) |
82 | 0 | return -1; |
83 | 46 | memset(op, 0x00, sizeof(*op)); |
84 | | |
85 | 46 | op->alproto = alproto; |
86 | 46 | op->LogFunc = LogFunc; |
87 | 46 | op->LogCondition = LogCondition; |
88 | 46 | op->output_ctx = output_ctx; |
89 | 46 | op->name = name; |
90 | 46 | op->logger_id = id; |
91 | 46 | op->ThreadInit = ThreadInit; |
92 | 46 | op->ThreadDeinit = ThreadDeinit; |
93 | 46 | op->ThreadExitPrintStats = ThreadExitPrintStats; |
94 | | |
95 | 46 | if (alproto == ALPROTO_UNKNOWN) { |
96 | 2 | op->tc_log_progress = 0; |
97 | 44 | } else if (tc_log_progress < 0) { |
98 | 40 | op->tc_log_progress = |
99 | 40 | AppLayerParserGetStateProgressCompletionStatus(alproto, |
100 | 40 | STREAM_TOCLIENT); |
101 | 40 | } else { |
102 | 4 | op->tc_log_progress = tc_log_progress; |
103 | 4 | } |
104 | | |
105 | 46 | if (alproto == ALPROTO_UNKNOWN) { |
106 | 2 | op->ts_log_progress = 0; |
107 | 44 | } else if (ts_log_progress < 0) { |
108 | 40 | op->ts_log_progress = |
109 | 40 | AppLayerParserGetStateProgressCompletionStatus(alproto, |
110 | 40 | STREAM_TOSERVER); |
111 | 40 | } else { |
112 | 4 | op->ts_log_progress = ts_log_progress; |
113 | 4 | } |
114 | | |
115 | 46 | if (list[alproto] == NULL) { |
116 | 40 | op->id = 1; |
117 | 40 | list[alproto] = op; |
118 | 40 | } else { |
119 | 6 | OutputTxLogger *t = list[alproto]; |
120 | 8 | while (t->next) |
121 | 2 | t = t->next; |
122 | 6 | if (t->id * 2ULL > UINT32_MAX) { |
123 | 0 | FatalError("Too many loggers registered."); |
124 | 0 | } |
125 | 6 | op->id = t->id * 2; |
126 | 6 | t->next = op; |
127 | 6 | } |
128 | | |
129 | 46 | SCLogDebug("OutputRegisterTxLogger happy"); |
130 | 46 | return 0; |
131 | 46 | } |
132 | | |
133 | | extern bool g_file_logger_enabled; |
134 | | extern bool g_filedata_logger_enabled; |
135 | | |
136 | | /** \brief run the per tx file logging |
137 | | * \todo clean up various end of tx/stream etc indicators |
138 | | */ |
139 | | static inline void OutputTxLogFiles(ThreadVars *tv, OutputFileLoggerThreadData *file_td, |
140 | | OutputFiledataLoggerThreadData *filedata_td, Packet *p, Flow *f, void *tx, |
141 | | const uint64_t tx_id, AppLayerTxData *txd, const bool tx_complete, const bool ts_ready, |
142 | | const bool tc_ready, const bool ts_eof, const bool tc_eof, const bool eof) |
143 | 21.3M | { |
144 | 21.3M | uint8_t packet_dir; |
145 | 21.3M | uint8_t opposing_dir; |
146 | 21.3M | bool packet_dir_ready; |
147 | 21.3M | const bool opposing_dir_ready = eof; |
148 | 21.3M | bool opposing_tx_ready; |
149 | 21.3M | if (p->flowflags & FLOW_PKT_TOSERVER) { |
150 | 10.6M | packet_dir = STREAM_TOSERVER; |
151 | 10.6M | opposing_dir = STREAM_TOCLIENT; |
152 | 10.6M | packet_dir_ready = eof | ts_ready | ts_eof; |
153 | 10.6M | opposing_tx_ready = tc_ready; |
154 | 10.7M | } else if (p->flowflags & FLOW_PKT_TOCLIENT) { |
155 | 10.7M | packet_dir = STREAM_TOCLIENT; |
156 | 10.7M | opposing_dir = STREAM_TOSERVER; |
157 | 10.7M | packet_dir_ready = eof | tc_ready | tc_eof; |
158 | 10.7M | opposing_tx_ready = ts_ready; |
159 | 10.7M | } else { |
160 | 0 | abort(); |
161 | 0 | } |
162 | | |
163 | 21.3M | SCLogDebug("eof %d ts_ready %d ts_eof %d", eof, ts_ready, ts_eof); |
164 | 21.3M | SCLogDebug("eof %d tc_ready %d tc_eof %d", eof, tc_ready, tc_eof); |
165 | | |
166 | 21.3M | SCLogDebug("packet dir %s opposing %s packet_dir_ready %d opposing_dir_ready %d", |
167 | 21.3M | packet_dir == STREAM_TOSERVER ? "TOSERVER" : "TOCLIENT", |
168 | 21.3M | opposing_dir == STREAM_TOSERVER ? "TOSERVER" : "TOCLIENT", packet_dir_ready, |
169 | 21.3M | opposing_dir_ready); |
170 | | |
171 | 21.3M | AppLayerGetFileState app_files = |
172 | 21.3M | AppLayerParserGetTxFiles(f, FlowGetAppState(f), tx, packet_dir); |
173 | 21.3M | FileContainer *ffc = app_files.fc; |
174 | 21.3M | AppLayerGetFileState app_files_opposing = |
175 | 21.3M | AppLayerParserGetTxFiles(f, FlowGetAppState(f), tx, opposing_dir); |
176 | 21.3M | FileContainer *ffc_opposing = app_files_opposing.fc; |
177 | | |
178 | | /* see if opposing side is finished: if no file support in this direction, of is not |
179 | | * files and tx is done for opposing dir. */ |
180 | 21.3M | bool opposing_finished = |
181 | 21.3M | ffc_opposing == NULL || (ffc_opposing->head == NULL && opposing_tx_ready); |
182 | 21.3M | SCLogDebug("opposing_finished %d ffc_opposing %p ffc_opposing->head %p opposing_tx_ready %d", |
183 | 21.3M | opposing_finished, ffc_opposing, ffc_opposing ? ffc_opposing->head : NULL, |
184 | 21.3M | opposing_tx_ready); |
185 | | |
186 | 21.3M | if (ffc || ffc_opposing) |
187 | 21.3M | SCLogDebug("pcap_cnt %" PRIu64 " flow %p tx %p tx_id %" PRIu64 |
188 | 21.3M | " ffc %p ffc_opposing %p tx_complete %d", |
189 | 21.3M | p->pcap_cnt, f, tx, tx_id, ffc, ffc_opposing, tx_complete); |
190 | | |
191 | 21.3M | if (ffc) { |
192 | 21.3M | const bool file_close = ((p->flags & PKT_PSEUDO_STREAM_END)) | eof; |
193 | 21.3M | const bool file_trunc = StreamTcpReassembleDepthReached(p) | eof; |
194 | 21.3M | SCLogDebug("tx: calling files: ffc %p head %p file_close %d file_trunc %d", ffc, ffc->head, |
195 | 21.3M | file_close, file_trunc); |
196 | 21.3M | if (filedata_td && txd->files_opened > txd->files_stored) |
197 | 788k | OutputFiledataLogFfc(tv, filedata_td, p, app_files, tx, tx_id, txd, packet_dir, |
198 | 788k | file_close, file_trunc, packet_dir); |
199 | 21.3M | if (file_td && txd->files_opened > txd->files_logged) |
200 | 788k | OutputFileLogFfc( |
201 | 788k | tv, file_td, p, ffc, tx, tx_id, txd, file_close, file_trunc, packet_dir); |
202 | 21.3M | } |
203 | | /* if EOF and we support files, do a final write out */ |
204 | 21.3M | if (opposing_dir_ready && ffc_opposing != NULL) { |
205 | 28.5k | const bool file_close = ((p->flags & PKT_PSEUDO_STREAM_END)) | tx_complete | eof; |
206 | 28.5k | const bool file_trunc = StreamTcpReassembleDepthReached(p) | eof; |
207 | 28.5k | opposing_finished = true; |
208 | 28.5k | SCLogDebug("tx: calling for opposing direction files: file_close:%s file_trunc:%s", |
209 | 28.5k | file_close ? "true" : "false", file_trunc ? "true" : "false"); |
210 | 28.5k | if (filedata_td && txd->files_opened > txd->files_stored) |
211 | 1.01k | OutputFiledataLogFfc(tv, filedata_td, p, app_files_opposing, tx, tx_id, txd, |
212 | 1.01k | opposing_dir, file_close, file_trunc, opposing_dir); |
213 | 28.5k | if (file_td && txd->files_opened > txd->files_logged) |
214 | 1.01k | OutputFileLogFfc(tv, file_td, p, ffc_opposing, tx, tx_id, txd, file_close, file_trunc, |
215 | 1.01k | opposing_dir); |
216 | 28.5k | } |
217 | | |
218 | 21.3M | const bool tx_done = packet_dir_ready && opposing_finished; |
219 | 21.3M | SCLogDebug("tx_done %d packet_dir_ready %d opposing_finished %d", tx_done, packet_dir_ready, |
220 | 21.3M | opposing_finished); |
221 | | |
222 | | /* if not a file tx or if tx is done, set logger flags so tx can move on */ |
223 | 21.3M | const bool is_file_tx = (ffc != NULL || ffc_opposing != NULL); |
224 | 21.3M | if (!is_file_tx || tx_done) { |
225 | 100k | SCLogDebug("is_file_tx %d tx_done %d", is_file_tx, tx_done); |
226 | 100k | if (file_td) { |
227 | 100k | txd->logged.flags |= BIT_U32(LOGGER_FILE); |
228 | 100k | SCLogDebug("setting LOGGER_FILE => %08x", txd->logged.flags); |
229 | 100k | } |
230 | 100k | if (filedata_td) { |
231 | 100k | txd->logged.flags |= BIT_U32(LOGGER_FILEDATA); |
232 | 100k | SCLogDebug("setting LOGGER_FILEDATA => %08x", txd->logged.flags); |
233 | 100k | } |
234 | 21.2M | } else { |
235 | 21.2M | SCLogDebug("pcap_cnt %" PRIu64 " flow %p tx %p tx_id %" PRIu64 |
236 | 21.2M | " NOT SETTING FILE FLAGS ffc %p ffc_opposing %p tx_complete %d", |
237 | 21.2M | p->pcap_cnt, f, tx, tx_id, ffc, ffc_opposing, tx_complete); |
238 | 21.2M | } |
239 | 21.3M | } |
240 | | |
241 | | static void OutputTxLogList0(ThreadVars *tv, OutputTxLoggerThreadData *op_thread_data, Packet *p, |
242 | | Flow *f, void *tx, const uint64_t tx_id) |
243 | 56.3M | { |
244 | 56.3M | const OutputTxLogger *logger = list[ALPROTO_UNKNOWN]; |
245 | 56.3M | const OutputLoggerThreadStore *store = op_thread_data->store[ALPROTO_UNKNOWN]; |
246 | | |
247 | 56.3M | DEBUG_VALIDATE_BUG_ON(logger == NULL && store != NULL); |
248 | 56.3M | DEBUG_VALIDATE_BUG_ON(logger != NULL && store == NULL); |
249 | 56.3M | DEBUG_VALIDATE_BUG_ON(logger == NULL && store == NULL); |
250 | | |
251 | 112M | while (logger && store) { |
252 | 56.3M | DEBUG_VALIDATE_BUG_ON(logger->LogFunc == NULL); |
253 | | |
254 | 56.3M | SCLogDebug("logger %p", logger); |
255 | | |
256 | | /* always invoke "wild card" tx loggers */ |
257 | 56.3M | SCLogDebug("Logging tx_id %"PRIu64" to logger %d", tx_id, logger->logger_id); |
258 | 56.3M | PACKET_PROFILING_LOGGER_START(p, logger->logger_id); |
259 | 56.3M | logger->LogFunc(tv, store->thread_data, p, f, f->alstate, tx, tx_id); |
260 | 56.3M | PACKET_PROFILING_LOGGER_END(p, logger->logger_id); |
261 | | |
262 | 56.3M | logger = logger->next; |
263 | 56.3M | store = store->next; |
264 | | |
265 | 56.3M | DEBUG_VALIDATE_BUG_ON(logger == NULL && store != NULL); |
266 | 56.3M | DEBUG_VALIDATE_BUG_ON(logger != NULL && store == NULL); |
267 | 56.3M | } |
268 | 56.3M | } |
269 | | |
270 | | struct Ctx { |
271 | | uint32_t tx_logged_old; |
272 | | uint32_t tx_logged; |
273 | | }; |
274 | | |
275 | | static void OutputTxLogCallLoggers(ThreadVars *tv, OutputTxLoggerThreadData *op_thread_data, |
276 | | const OutputTxLogger *logger, const OutputLoggerThreadStore *store, Packet *p, Flow *f, |
277 | | void *alstate, void *tx, const uint64_t tx_id, const AppProto alproto, const bool eof, |
278 | | const int tx_progress_ts, const int tx_progress_tc, struct Ctx *ctx) |
279 | 22.7M | { |
280 | 22.7M | DEBUG_VALIDATE_BUG_ON(logger == NULL && store != NULL); |
281 | 22.7M | DEBUG_VALIDATE_BUG_ON(logger != NULL && store == NULL); |
282 | | // DEBUG_VALIDATE_BUG_ON(logger == NULL && store == NULL); |
283 | | |
284 | 65.8M | while (logger && store) { |
285 | 43.1M | DEBUG_VALIDATE_BUG_ON(logger->LogFunc == NULL); |
286 | 43.1M | DEBUG_VALIDATE_BUG_ON(logger->alproto != alproto); |
287 | | |
288 | 43.1M | SCLogDebug("logger %p, Alproto %d LogCondition %p, ts_log_progress %d " |
289 | 43.1M | "tc_log_progress %d", |
290 | 43.1M | logger, logger->alproto, logger->LogCondition, logger->ts_log_progress, |
291 | 43.1M | logger->tc_log_progress); |
292 | 43.1M | if ((ctx->tx_logged_old & BIT_U32(logger->logger_id)) == 0) { |
293 | 43.0M | SCLogDebug("alproto match %d, logging tx_id %" PRIu64, logger->alproto, tx_id); |
294 | | |
295 | 43.0M | SCLogDebug("pcap_cnt %" PRIu64 ", tx_id %" PRIu64 " logger %d. EOF %s", p->pcap_cnt, |
296 | 43.0M | tx_id, logger->logger_id, eof ? "true" : "false"); |
297 | | |
298 | 43.0M | if (eof) { |
299 | 105k | SCLogDebug("EOF, so log now"); |
300 | 42.9M | } else { |
301 | 42.9M | if (logger->LogCondition) { |
302 | 570k | int r = logger->LogCondition(tv, p, alstate, tx, tx_id); |
303 | 570k | if (r == FALSE) { |
304 | 570k | SCLogDebug("conditions not met, not logging"); |
305 | 570k | goto next_logger; |
306 | 570k | } |
307 | 42.3M | } else { |
308 | 42.3M | if (tx_progress_tc < logger->tc_log_progress) { |
309 | 35.7M | SCLogDebug("progress not far enough, not logging"); |
310 | 35.7M | goto next_logger; |
311 | 35.7M | } |
312 | | |
313 | 6.60M | if (tx_progress_ts < logger->ts_log_progress) { |
314 | 6.28M | SCLogDebug("progress not far enough, not logging"); |
315 | 6.28M | goto next_logger; |
316 | 6.28M | } |
317 | 6.60M | } |
318 | 42.9M | } |
319 | | |
320 | 420k | SCLogDebug("Logging tx_id %" PRIu64 " to logger %d", tx_id, logger->logger_id); |
321 | 420k | PACKET_PROFILING_LOGGER_START(p, logger->logger_id); |
322 | 420k | logger->LogFunc(tv, store->thread_data, p, f, alstate, tx, tx_id); |
323 | 420k | PACKET_PROFILING_LOGGER_END(p, logger->logger_id); |
324 | | |
325 | 420k | ctx->tx_logged |= BIT_U32(logger->logger_id); |
326 | 420k | } |
327 | | |
328 | 43.1M | next_logger: |
329 | 43.1M | logger = logger->next; |
330 | 43.1M | store = store->next; |
331 | | |
332 | 43.1M | DEBUG_VALIDATE_BUG_ON(logger == NULL && store != NULL); |
333 | 43.1M | DEBUG_VALIDATE_BUG_ON(logger != NULL && store == NULL); |
334 | 43.1M | } |
335 | 22.7M | } |
336 | | |
337 | | static TmEcode OutputTxLog(ThreadVars *tv, Packet *p, void *thread_data) |
338 | 9.54M | { |
339 | 9.54M | DEBUG_VALIDATE_BUG_ON(thread_data == NULL); |
340 | 9.54M | if (p->flow == NULL) |
341 | 1.83M | return TM_ECODE_OK; |
342 | 7.70M | if (!PKT_IS_PSEUDOPKT(p) && p->app_update_direction == 0 && |
343 | 5.82M | ((PKT_IS_TOSERVER(p) && (p->flow->flags & FLOW_TS_APP_UPDATED) == 0) || |
344 | 5.29M | (PKT_IS_TOCLIENT(p) && (p->flow->flags & FLOW_TC_APP_UPDATED) == 0))) { |
345 | 5.29M | SCLogDebug("not pseudo, no app update: skip"); |
346 | 5.29M | return TM_ECODE_OK; |
347 | 5.29M | } |
348 | 2.40M | SCLogDebug("pseudo, or app update: run output"); |
349 | | |
350 | 2.40M | OutputTxLoggerThreadData *op_thread_data = (OutputTxLoggerThreadData *)thread_data; |
351 | | |
352 | 2.40M | Flow * const f = p->flow; |
353 | 2.40M | const uint8_t ipproto = f->proto; |
354 | 2.40M | const AppProto alproto = f->alproto; |
355 | 2.40M | SCLogDebug("pcap_cnt %u tx logging %u/%s", (uint32_t)p->pcap_cnt, alproto, |
356 | 2.40M | AppProtoToString(alproto)); |
357 | | |
358 | 2.40M | const bool file_logging_active = (op_thread_data->file || op_thread_data->filedata); |
359 | 2.40M | if (!file_logging_active) { |
360 | 0 | if (list[alproto] == NULL && list[ALPROTO_UNKNOWN] == NULL) { |
361 | 0 | SCLogDebug("bail"); |
362 | | /* No child loggers registered. */ |
363 | 0 | return TM_ECODE_OK; |
364 | 0 | } |
365 | 0 | if (AppLayerParserProtocolHasLogger(ipproto, alproto) == 0) |
366 | 0 | goto end; |
367 | 0 | } |
368 | 2.40M | void *alstate = f->alstate; |
369 | 2.40M | if (alstate == NULL) { |
370 | 108k | SCLogDebug("no alstate"); |
371 | 108k | goto end; |
372 | 108k | } |
373 | 2.30M | const LoggerId logger_expectation = AppLayerParserProtocolGetLoggerBits(ipproto, alproto); |
374 | 2.30M | if (logger_expectation == 0) { |
375 | 266k | SCLogDebug("bail: logger_expectation %u. LOGGER_FILE %u LOGGER_FILEDATA %u", |
376 | 266k | logger_expectation, LOGGER_FILE, LOGGER_FILEDATA); |
377 | 266k | goto end; |
378 | 266k | } |
379 | 2.03M | SCLogDebug("pcap_cnt %" PRIu64, p->pcap_cnt); |
380 | | |
381 | 2.03M | const bool last_pseudo = (p->flowflags & FLOW_PKT_LAST_PSEUDO) != 0; |
382 | 2.03M | const bool ts_eof = AppLayerParserStateIssetFlag(f->alparser, |
383 | 2.03M | (APP_LAYER_PARSER_EOF_TS | APP_LAYER_PARSER_TRUNC_TS)) != 0; |
384 | 2.03M | const bool tc_eof = AppLayerParserStateIssetFlag(f->alparser, |
385 | 2.03M | (APP_LAYER_PARSER_EOF_TC | APP_LAYER_PARSER_TRUNC_TC)) != 0; |
386 | | |
387 | 2.03M | const bool eof = last_pseudo || (ts_eof && tc_eof); |
388 | 2.03M | SCLogDebug("eof %d last_pseudo %d ts_eof %d tc_eof %d", eof, last_pseudo, ts_eof, tc_eof); |
389 | | |
390 | 2.03M | const uint8_t ts_disrupt_flags = FlowGetDisruptionFlags(f, STREAM_TOSERVER); |
391 | 2.03M | const uint8_t tc_disrupt_flags = FlowGetDisruptionFlags(f, STREAM_TOCLIENT); |
392 | 2.03M | SCLogDebug("ts_disrupt_flags %02x tc_disrupt_flags %02x", ts_disrupt_flags, tc_disrupt_flags); |
393 | 2.03M | const uint64_t total_txs = AppLayerParserGetTxCnt(f, alstate); |
394 | 2.03M | uint64_t tx_id = AppLayerParserGetTransactionLogId(f->alparser); |
395 | 2.03M | uint64_t max_id = tx_id; |
396 | 2.03M | int logged = 0; |
397 | 2.03M | bool gap = false; |
398 | 2.03M | const bool support_files = AppLayerParserSupportsFiles(ipproto, alproto); |
399 | 2.03M | const uint8_t pkt_dir = STREAM_FLAGS_FOR_PACKET(p); |
400 | | |
401 | 2.03M | SCLogDebug("pcap_cnt %" PRIu64 ": tx_id %" PRIu64 " total_txs %" PRIu64, p->pcap_cnt, tx_id, |
402 | 2.03M | total_txs); |
403 | | |
404 | 2.03M | AppLayerGetTxIteratorFunc IterFunc = AppLayerGetTxIterator(ipproto, alproto); |
405 | 2.03M | AppLayerGetTxIterState state; |
406 | 2.03M | memset(&state, 0, sizeof(state)); |
407 | | |
408 | 2.03M | const int complete_ts = |
409 | 2.03M | AppLayerParserGetStateProgressCompletionStatus(alproto, STREAM_TOSERVER); |
410 | 2.03M | const int complete_tc = |
411 | 2.03M | AppLayerParserGetStateProgressCompletionStatus(alproto, STREAM_TOCLIENT); |
412 | 25.3M | while (1) { |
413 | 25.3M | AppLayerGetTxIterTuple ires = IterFunc(ipproto, alproto, alstate, tx_id, total_txs, &state); |
414 | 25.3M | if (ires.tx_ptr == NULL) |
415 | 270k | break; |
416 | 25.0M | void * const tx = ires.tx_ptr; |
417 | 25.0M | tx_id = ires.tx_id; |
418 | 25.0M | SCLogDebug("STARTING tx_id %" PRIu64 ", tx %p", tx_id, tx); |
419 | | |
420 | 25.0M | AppLayerTxData *txd = AppLayerParserGetTxData(ipproto, alproto, tx); |
421 | 25.0M | if (unlikely(txd == NULL)) { |
422 | 0 | SCLogDebug("NO TXD"); |
423 | | /* make sure this tx, which can't be properly logged is skipped */ |
424 | 0 | logged = 1; |
425 | 0 | max_id = tx_id; |
426 | 0 | goto next_tx; |
427 | 0 | } |
428 | | |
429 | 25.0M | const int tx_progress_ts = |
430 | 25.0M | AppLayerParserGetStateProgress(ipproto, alproto, tx, ts_disrupt_flags); |
431 | 25.0M | const int tx_progress_tc = |
432 | 25.0M | AppLayerParserGetStateProgress(ipproto, alproto, tx, tc_disrupt_flags); |
433 | 25.0M | const bool tx_complete = (tx_progress_ts == complete_ts && tx_progress_tc == complete_tc); |
434 | | |
435 | 25.0M | SCLogDebug("file_thread_data %p filedata_thread_data %p", op_thread_data->file, |
436 | 25.0M | op_thread_data->filedata); |
437 | | |
438 | 25.0M | if (file_logging_active) { |
439 | 25.0M | if (AppLayerParserIsFileTx(txd)) { // need to process each tx that might be a file tx, |
440 | | // even if there are not files (yet) |
441 | 21.4M | const bool ts_ready = (tx_progress_ts == complete_ts); |
442 | 21.4M | const bool tc_ready = (tx_progress_tc == complete_tc); |
443 | 21.4M | SCLogDebug("ts_ready %d tc_ready %d", ts_ready, tc_ready); |
444 | | |
445 | 21.4M | const bool eval_files = ts_ready | tc_ready | tx_complete | ts_eof | tc_eof | eof; |
446 | | |
447 | 21.4M | SCLogDebug("eval_files: %u, ts_ready %u, tc_ready %u, tx_complete %u, ts_eof %u, " |
448 | 21.4M | "tc_eof %u, eof %u", |
449 | 21.4M | eval_files, ts_ready, tc_ready, tx_complete, ts_eof, tc_eof, eof); |
450 | 21.4M | SCLogDebug("txd->file_tx & pkt_dir: %02x & %02x -> %02x", txd->file_tx, pkt_dir, |
451 | 21.4M | (txd->file_tx & pkt_dir)); |
452 | | |
453 | | /* call only for the correct direction, except when it looks anything like a end of |
454 | | * transaction or end of stream. Since OutputTxLogFiles has complicated logic around |
455 | | * that, we just leave it to that function to sort things out for now. */ |
456 | 21.4M | if (eval_files || AppLayerParserIsFileTxInDir(txd, pkt_dir)) { |
457 | 21.3M | OutputTxLogFiles(tv, op_thread_data->file, op_thread_data->filedata, p, f, tx, |
458 | 21.3M | tx_id, txd, tx_complete, ts_ready, tc_ready, ts_eof, tc_eof, eof); |
459 | 21.3M | } |
460 | 21.4M | } else if (support_files) { |
461 | 2.78M | if (op_thread_data->file) { |
462 | 2.78M | txd->logged.flags |= BIT_U32(LOGGER_FILE); |
463 | 2.78M | SCLogDebug("not a file_tx: setting LOGGER_FILE => %08x", txd->logged.flags); |
464 | 2.78M | } |
465 | 2.78M | if (op_thread_data->filedata) { |
466 | 2.78M | txd->logged.flags |= BIT_U32(LOGGER_FILEDATA); |
467 | 2.78M | SCLogDebug("not a file_tx: setting LOGGER_FILEDATA => %08x", txd->logged.flags); |
468 | 2.78M | } |
469 | 2.78M | } |
470 | 25.0M | } |
471 | 25.0M | SCLogDebug("logger: expect %08x, have %08x", logger_expectation, txd->logged.flags); |
472 | 25.0M | if (!txd->updated_tc && !txd->updated_ts && !(tx_progress_ts == complete_ts) && |
473 | 5.14M | !(tx_progress_tc == complete_tc) && !ts_eof && !tc_eof) { |
474 | 2.04M | gap = true; |
475 | 2.04M | goto next_tx; |
476 | 2.04M | } |
477 | | |
478 | 23.0M | if (list[ALPROTO_UNKNOWN] != 0) { |
479 | 23.0M | OutputTxLogList0(tv, op_thread_data, p, f, tx, tx_id); |
480 | 23.0M | if (list[alproto] == NULL) |
481 | 167k | goto next_tx; |
482 | 23.0M | } |
483 | | |
484 | 22.8M | SCLogDebug("tx %p/%" PRIu64 " txd %p: log_flags %x logger_expectation %x", tx, tx_id, txd, |
485 | 22.8M | txd->config.log_flags, logger_expectation); |
486 | 22.8M | if (txd->config.log_flags & BIT_U8(CONFIG_TYPE_TX)) { |
487 | 50 | SCLogDebug("SKIP tx %p/%"PRIu64, tx, tx_id); |
488 | | // so that AppLayerParserTransactionsCleanup can clean this tx |
489 | 50 | txd->logged.flags |= logger_expectation; |
490 | 50 | goto next_tx; |
491 | 50 | } |
492 | | |
493 | 22.8M | if (txd->logged.flags == logger_expectation) { |
494 | 106k | SCLogDebug("fully logged"); |
495 | | /* tx already fully logged */ |
496 | 106k | goto next_tx; |
497 | 106k | } |
498 | | |
499 | 22.7M | SCLogDebug("logger: expect %08x, have %08x", logger_expectation, txd->logged.flags); |
500 | 22.7M | const OutputTxLogger *logger = list[alproto]; |
501 | 22.7M | const OutputLoggerThreadStore *store = op_thread_data->store[alproto]; |
502 | 22.7M | struct Ctx ctx = { .tx_logged = txd->logged.flags, .tx_logged_old = txd->logged.flags }; |
503 | 22.7M | SCLogDebug("logger: expect %08x, have %08x", logger_expectation, ctx.tx_logged); |
504 | | |
505 | 22.7M | OutputTxLogCallLoggers(tv, op_thread_data, logger, store, p, f, alstate, tx, tx_id, alproto, |
506 | 22.7M | eof, tx_progress_ts, tx_progress_tc, &ctx); |
507 | | |
508 | 22.7M | SCLogDebug("logger: expect %08x, have %08x", logger_expectation, ctx.tx_logged); |
509 | 22.7M | if (ctx.tx_logged != ctx.tx_logged_old) { |
510 | 333k | SCLogDebug("logger: storing %08x (was %08x)", ctx.tx_logged, ctx.tx_logged_old); |
511 | 333k | DEBUG_VALIDATE_BUG_ON(txd == NULL); |
512 | 333k | txd->logged.flags |= ctx.tx_logged; |
513 | 333k | } |
514 | | |
515 | | /* If all loggers logged set a flag and update the last tx_id |
516 | | * that was logged. |
517 | | * |
518 | | * If not all loggers were logged we flag that there was a gap |
519 | | * so any subsequent transactions in this loop don't increase |
520 | | * the maximum ID that was logged. */ |
521 | 22.7M | if (!gap && ctx.tx_logged == logger_expectation) { |
522 | 246k | SCLogDebug("no gap %d, %08x == %08x", gap, ctx.tx_logged, logger_expectation); |
523 | 246k | logged = 1; |
524 | 246k | max_id = tx_id; |
525 | 246k | SCLogDebug("max_id %" PRIu64, max_id); |
526 | 22.5M | } else { |
527 | 22.5M | gap = true; |
528 | 22.5M | } |
529 | 25.0M | next_tx: |
530 | 25.0M | if (!ires.has_next) |
531 | 1.76M | break; |
532 | 23.3M | tx_id++; |
533 | 23.3M | } |
534 | | |
535 | | /* Update the last ID that has been logged with all |
536 | | * transactions before it. */ |
537 | 2.03M | if (logged) { |
538 | 202k | SCLogDebug("updating log tx_id %"PRIu64, max_id); |
539 | 202k | AppLayerParserSetTransactionLogId(f->alparser, max_id + 1); |
540 | 202k | } |
541 | | |
542 | 2.40M | end: |
543 | 2.40M | return TM_ECODE_OK; |
544 | 2.03M | } |
545 | | |
546 | | /** \brief thread init for the tx logger |
547 | | * This will run the thread init functions for the individual registered |
548 | | * loggers */ |
549 | | static TmEcode OutputTxLogThreadInit(ThreadVars *tv, const void *_initdata, void **data) |
550 | 4 | { |
551 | 4 | OutputTxLoggerThreadData *td = SCMalloc(sizeof(*td)); |
552 | 4 | if (td == NULL) |
553 | 0 | return TM_ECODE_FAILED; |
554 | 4 | memset(td, 0x00, sizeof(*td)); |
555 | | |
556 | 4 | *data = (void *)td; |
557 | 4 | SCLogDebug("OutputTxLogThreadInit happy (*data %p)", *data); |
558 | | |
559 | 154 | for (AppProto alproto = 0; alproto < ALPROTO_MAX; alproto++) { |
560 | 150 | OutputTxLogger *logger = list[alproto]; |
561 | 240 | while (logger) { |
562 | 90 | if (logger->ThreadInit) { |
563 | 90 | void *retptr = NULL; |
564 | 90 | if (logger->ThreadInit(tv, (void *)logger->output_ctx, &retptr) == TM_ECODE_OK) { |
565 | 90 | OutputLoggerThreadStore *ts = SCMalloc(sizeof(*ts)); |
566 | 90 | /* todo */ BUG_ON(ts == NULL); |
567 | 90 | memset(ts, 0x00, sizeof(*ts)); |
568 | | |
569 | | /* store thread handle */ |
570 | 90 | ts->thread_data = retptr; |
571 | | |
572 | 90 | if (td->store[alproto] == NULL) { |
573 | 80 | td->store[alproto] = ts; |
574 | 80 | } else { |
575 | 10 | OutputLoggerThreadStore *tmp = td->store[alproto]; |
576 | 12 | while (tmp->next != NULL) |
577 | 2 | tmp = tmp->next; |
578 | 10 | tmp->next = ts; |
579 | 10 | } |
580 | | |
581 | 90 | SCLogDebug("%s is now set up", logger->name); |
582 | 90 | } |
583 | 90 | } |
584 | | |
585 | 90 | logger = logger->next; |
586 | 90 | } |
587 | 150 | } |
588 | | |
589 | 4 | if (g_file_logger_enabled) { |
590 | 4 | if (OutputFileLogThreadInit(tv, &td->file) != TM_ECODE_OK) { |
591 | 0 | FatalError("failed to set up file thread data"); |
592 | 0 | } |
593 | 4 | } |
594 | 4 | if (g_filedata_logger_enabled) { |
595 | 4 | if (OutputFiledataLogThreadInit(tv, &td->filedata) != TM_ECODE_OK) { |
596 | 0 | FatalError("failed to set up filedata thread data"); |
597 | 0 | } |
598 | 4 | } |
599 | | |
600 | 4 | SCLogDebug("file_thread_data %p filedata_thread_data %p", td->file, td->filedata); |
601 | | |
602 | 4 | return TM_ECODE_OK; |
603 | 4 | } |
604 | | |
605 | | static TmEcode OutputTxLogThreadDeinit(ThreadVars *tv, void *thread_data) |
606 | 0 | { |
607 | 0 | OutputTxLoggerThreadData *op_thread_data = (OutputTxLoggerThreadData *)thread_data; |
608 | |
|
609 | 0 | for (AppProto alproto = 0; alproto < ALPROTO_MAX; alproto++) { |
610 | 0 | OutputLoggerThreadStore *store = op_thread_data->store[alproto]; |
611 | 0 | OutputTxLogger *logger = list[alproto]; |
612 | |
|
613 | 0 | while (logger && store) { |
614 | 0 | if (logger->ThreadDeinit) { |
615 | 0 | logger->ThreadDeinit(tv, store->thread_data); |
616 | 0 | } |
617 | |
|
618 | 0 | OutputLoggerThreadStore *next_store = store->next; |
619 | 0 | SCFree(store); |
620 | 0 | store = next_store; |
621 | 0 | logger = logger->next; |
622 | 0 | } |
623 | 0 | } |
624 | |
|
625 | 0 | if (op_thread_data->file) { |
626 | 0 | OutputFileLogThreadDeinit(tv, op_thread_data->file); |
627 | 0 | } |
628 | 0 | if (op_thread_data->filedata) { |
629 | 0 | OutputFiledataLogThreadDeinit(tv, op_thread_data->filedata); |
630 | 0 | } |
631 | |
|
632 | 0 | SCFree(op_thread_data); |
633 | 0 | return TM_ECODE_OK; |
634 | 0 | } |
635 | | |
636 | | static void OutputTxLogExitPrintStats(ThreadVars *tv, void *thread_data) |
637 | 0 | { |
638 | 0 | OutputTxLoggerThreadData *op_thread_data = (OutputTxLoggerThreadData *)thread_data; |
639 | |
|
640 | 0 | for (AppProto alproto = 0; alproto < ALPROTO_MAX; alproto++) { |
641 | 0 | OutputLoggerThreadStore *store = op_thread_data->store[alproto]; |
642 | 0 | OutputTxLogger *logger = list[alproto]; |
643 | |
|
644 | 0 | while (logger && store) { |
645 | 0 | if (logger->ThreadExitPrintStats) { |
646 | 0 | logger->ThreadExitPrintStats(tv, store->thread_data); |
647 | 0 | } |
648 | |
|
649 | 0 | logger = logger->next; |
650 | 0 | store = store->next; |
651 | 0 | } |
652 | 0 | } |
653 | 0 | } |
654 | | |
655 | | static uint32_t OutputTxLoggerGetActiveCount(void) |
656 | 2 | { |
657 | 2 | uint32_t cnt = 0; |
658 | 72 | for (AppProto alproto = 0; alproto < ALPROTO_MAX; alproto++) { |
659 | 116 | for (OutputTxLogger *p = list[alproto]; p != NULL; p = p->next) { |
660 | 46 | cnt++; |
661 | 46 | } |
662 | 70 | } |
663 | | |
664 | 2 | if (g_file_logger_enabled) { |
665 | 2 | cnt++; |
666 | 2 | SCLogDebug("g_file_logger_enabled"); |
667 | 2 | } |
668 | 2 | if (g_filedata_logger_enabled) { |
669 | 2 | cnt++; |
670 | 2 | SCLogDebug("g_filedata_logger_enabled"); |
671 | 2 | } |
672 | | |
673 | 2 | return cnt; |
674 | 2 | } |
675 | | |
676 | | |
677 | | void OutputTxLoggerRegister (void) |
678 | 33 | { |
679 | 33 | OutputRegisterRootLogger(OutputTxLogThreadInit, OutputTxLogThreadDeinit, |
680 | 33 | OutputTxLogExitPrintStats, OutputTxLog, OutputTxLoggerGetActiveCount); |
681 | 33 | } |
682 | | |
683 | | void OutputTxShutdown(void) |
684 | 0 | { |
685 | 0 | for (AppProto alproto = 0; alproto < ALPROTO_MAX; alproto++) { |
686 | 0 | OutputTxLogger *logger = list[alproto]; |
687 | 0 | while (logger) { |
688 | 0 | OutputTxLogger *next_logger = logger->next; |
689 | 0 | SCFree(logger); |
690 | 0 | logger = next_logger; |
691 | 0 | } |
692 | | list[alproto] = NULL; |
693 | 0 | } |
694 | 0 | } |