一、背景
在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 为啥需要临时变量
- 将可变参数格式化成一个字符串，需要一个存储空间
- 栈变量是线程安全的
- 简单通用
3.3 是否可以增加空间
可以增加SC_LOG_MAX_LOG_MSG_LEN的值，但是不推荐
- 每条日志大小一般都很小，2K已经满足90%以上的情况
- 栈变量太大，递归或深层调用可能会耗尽栈空间
// 栈默认大小（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 the
terminating null byte ('\0')). If the output was truncated due to this limit, then the
return value is the number of characters (excluding the terminating null byte) which would
have been written to the final string if enough space had been available. Thus, a return
value 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"
总结
日志截断问题的主要原因是日志内容经过两次格式化，且每次格式化都使用了固定大小的缓冲区。通过动态分配缓冲区，可以有效避免日志被截断的问题。
