一、背景

在suricata的調試過程中，使用SCLogXXX api進行信息的輸出，發現輸出的日志被截斷了，最開始以為是解析邏輯有問題，沒有解析完整，經過排查后，發現SCLogXXX api內部進行了長度限制，最長2K。

OS：Ubuntu 22.04.5 LTS
IDE: vscode
Suricata: suricata 7.0.5

二、 問題復現

拷貝一個規則，將規則內容填充任意內容，使其達到2K以上

規則重復時，輸出錯誤日志，日志截斷

三、分析

3.1 源碼實現

// src/util-debug.h
/* The maximum length of the log message */
#define SC_LOG_MAX_LOG_MSG_LEN 2048// src/util-debug.c
void SCLogErr(int x, const char *file, const char *func, const int line, const char *module,const char *fmt, ...)
{if (sc_log_global_log_level >= x &&(sc_log_fg_filters_present == 0 ||SCLogMatchFGFilterWL(file, func, line) == 1 ||SCLogMatchFGFilterBL(file, func, line) == 1) &&(sc_log_fd_filters_present == 0 ||SCLogMatchFDFilter(func) == 1)){char msg[SC_LOG_MAX_LOG_MSG_LEN];va_list ap;va_start(ap, fmt);vsnprintf(msg, sizeof(msg), fmt, ap);va_end(ap);SCLogMessage(x, file, line, func, module, msg);}
}

從實現中可以看出，首先將數據格式化到一個局部臨時變量中，再將臨時變量輸出。
而臨時變量是一個2K的字符數組，因此需要輸出的數據超過2K將被截斷。

3.2 為啥需要臨時變量

1. 將可變參數格式化成一個字符串，需要一個存儲空間
2. 棧變量是線程安全的
3. 簡單通用

3.3 是否可以增加空間

可以增加SC_LOG_MAX_LOG_MSG_LEN的值，但是不推薦

1. 每條日志大小一般都很小，2K已經滿足90%以上的情況
2. 棧變量太大，遞歸或深層調用可能會耗盡棧空間

// 棧默認大小（KB）
$ ulimit -s
8192 // 棧最大上限，受系統內存限制
$ ulimit -Hs
unlimited// glibc 中的默認值
$ getconf PTHREAD_STACK_MIN
16384

3.4 非要解決截斷問題如何處理

man vsnprintf

The  functions snprintf() and vsnprintf() do not write more than size bytes (including theterminating null byte ('\0')).  If the output was truncated due to this  limit,  then  thereturn value is the number of characters (excluding the terminating null byte) which wouldhave been written to the final string if enough space had been available.  Thus, a  returnvalue of size or more means that the output was truncated.  

根據man手冊的說明，可以判斷vsnprintf的返回值，返回值超過2048時，可以動態申請空間，再次進行格式化

    char msg[SC_LOG_MAX_LOG_MSG_LEN];char *real_msg = msg;va_list ap;va_start(ap, fmt);int ret = vsnprintf(msg, sizeof(msg), fmt, ap);va_end(ap);if (ret > SC_LOG_MAX_LOG_MSG_LEN) { // 被截斷real_msg = SCMalloc(ret+1); // 動態分配空間if (likely(real_msg != NULL)) {va_start(ap, fmt);vsnprintf(real_msg, ret+1, fmt, ap); // 重新格式化va_end(ap);} else {real_msg = msg; // 空間申請失敗}}SCLogMessage(x, file, line, func, module, real_msg);if (real_msg != msg) {SCFree(real_msg);}

結果是依然被截斷了，繼續分析SCLogMessage實現

SCError SCLogMessage(const SCLogLevel log_level, const char *file, const unsigned int line,const char *function, const char *module, const char *message)
{char buffer[SC_LOG_MAX_LOG_MSG_LEN] = "";...case SC_LOG_OP_IFACE_CONSOLE:if (SCLogMessageGetBuffer(ts, op_iface_ctx->use_color, op_iface_ctx->type, buffer,sizeof(buffer),op_iface_ctx->log_format ? op_iface_ctx->log_format: sc_log_config->log_format,log_level, file, line, function, module, message) == 0) {SCLogPrintToStream((log_level == SC_LOG_ERROR)? stderr: stdout, buffer);}break;...return SC_OK;
}

又一個buffer[SC_LOG_MAX_LOG_MSG_LEN], 再次被截斷

3.5 為啥是兩次格式化

第一次是將用戶輸入的信息格式化；
第二次增加額外信息(時間、函數名，行號等)，可通過配置決定添加的信息
suricata.yaml

logging:default-log-format: "%D: %S:%l %M"

總結

日志截斷問題的主要原因是日志內容經過兩次格式化，且每次格式化都使用了固定大小的緩沖區。通過動態分配緩沖區，可以有效避免日志被截斷的問題。