mirrors
/
redis
mirror of https://mirror.osredm.com/root/redis.git
2
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Print command tokens on a crash when hide-user-data-from-log is enabled (#13639) 

If `hide-user-data-from-log` config is enabled, we don't print client
argv in the crashlog to avoid leaking user info.
Though, debugging a crash becomes harder as we don't see the command
arguments causing the crash.

With this PR, we'll be printing command tokens to the log. As we have
command tokens defined in json schema for each command, using this data,
we can find tokens in the client argv.

e.g. 
`SET key value GET EX 10` ---> we'll print `SET * * GET EX *` in the
log.

Modules should introduce their command structure via
`RM_SetCommandInfo()`.
Then, on a crash we'll able to know module command tokens.
This commit is contained in:
Ozan Tezcan 2024-11-11 09:34:18 +03:00 committed by GitHub
parent fdeb97629e
commit 54038811c0
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
3 changed files with 418 additions and 22 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

80
src/debug.c
View File

@ -1052,6 +1052,46 @@ NULL
/* =========================== Crash handling ============================== */
/* When hide-user-data-from-log is enabled, to avoid leaking user info, we only
* print tokens of the current command into the log. First, we collect command
* tokens into this struct (Commands tokens are defined in json schema). Later,
* checking each argument against the token list. */
#define CMD_TOKEN_MAX_COUNT 128 /* Max token count in a command's json schema */
struct cmdToken {
const char *tokens[CMD_TOKEN_MAX_COUNT];
int n_token;
};
/* Collect tokens from command arguments recursively. */
static void cmdTokenCollect(struct cmdToken *tk, redisCommandArg *args, int argc) {
if (args == NULL)
return;
for (int i = 0; i < argc && tk->n_token < CMD_TOKEN_MAX_COUNT; i++) {
if (args[i].token)
tk->tokens[tk->n_token++] = args[i].token;
cmdTokenCollect(tk, args[i].subargs, args[i].num_args);
}
}
/* Get tokens of the command. */
static void cmdTokenGetFromCommand(struct cmdToken *tk, struct redisCommand *cmd) {
tk->n_token = 0;
cmdTokenCollect(tk, cmd->args, cmd->num_args);
}
/* Check if object is one of command's tokens. */
static int cmdTokenCheck(struct cmdToken *tk, robj *o) {
if (o->type != OBJ_STRING || !sdsEncodedObject(o))
return 0;
for (int i = 0; i < tk->n_token; i++) {
if (strcasecmp(tk->tokens[i], o->ptr) == 0)
return 1;
}
return 0;
}
__attribute__ ((noinline))
void _serverAssert(const char *estr, const char *file, int line) {
int new_report = bugReportStart();
@ -1072,28 +1112,35 @@ void _serverAssert(const char *estr, const char *file, int line) {
bugReportEnd(0, 0);
}
/* Returns the amount of client's command arguments we allow logging */
int clientArgsToLog(const client *c) {
return server.hide_user_data_from_log ? 1 : c->argc;
}
void _serverAssertPrintClientInfo(const client *c) {
int j;
char conninfo[CONN_INFO_LEN];
struct redisCommand *cmd = NULL;
struct cmdToken tokens = {{0}};
bugReportStart();
serverLog(LL_WARNING,"=== ASSERTION FAILED CLIENT CONTEXT ===");
serverLog(LL_WARNING,"client->flags = %llu", (unsigned long long) c->flags);
serverLog(LL_WARNING,"client->conn = %s", connGetInfo(c->conn, conninfo, sizeof(conninfo)));
serverLog(LL_WARNING,"client->argc = %d", c->argc);
for (j=0; j < c->argc; j++) {
if (j >= clientArgsToLog(c)) {
serverLog(LL_WARNING,"client->argv[%d] = *redacted*",j);
continue;
if (server.hide_user_data_from_log) {
cmd = lookupCommand(c->argv, c->argc);
if (cmd)
cmdTokenGetFromCommand(&tokens, cmd);
}
for (j=0; j < c->argc; j++) {
char buf[128];
char *arg;
/* Allow command name, subcommand name and command tokens in the log. */
if (server.hide_user_data_from_log && (j != 0 && !(j == 1 && cmd && cmd->parent))) {
if (!cmdTokenCheck(&tokens, c->argv[j])) {
serverLog(LL_WARNING, "client->argv[%d] = *redacted*", j);
continue;
}
}
if (c->argv[j]->type == OBJ_STRING && sdsEncodedObject(c->argv[j])) {
arg = (char*) c->argv[j]->ptr;
} else {
@ -2061,17 +2108,28 @@ void logCurrentClient(client *cc, const char *title) {
sds client;
int j;
struct redisCommand *cmd = NULL;
struct cmdToken tokens = {{0}};
serverLog(LL_WARNING|LL_RAW, "\n------ %s CLIENT INFO ------\n", title);
client = catClientInfoString(sdsempty(),cc);
serverLog(LL_WARNING|LL_RAW,"%s\n", client);
sdsfree(client);
serverLog(LL_WARNING|LL_RAW,"argc: '%d'\n", cc->argc);
if (server.hide_user_data_from_log) {
cmd = lookupCommand(cc->argv, cc->argc);
if (cmd)
cmdTokenGetFromCommand(&tokens, cmd);
}
for (j = 0; j < cc->argc; j++) {
if (j >= clientArgsToLog(cc)) {
serverLog(LL_WARNING|LL_RAW,"argv[%d]: *redacted*\n",j);
/* Allow command name, subcommand name and command tokens in the log. */
if (server.hide_user_data_from_log && (j != 0 && !(j == 1 && cmd && cmd->parent))) {
if (!cmdTokenCheck(&tokens, cc->argv[j])) {
serverLog(LL_WARNING|LL_RAW, "argv[%d]: '*redacted*'\n", j);
continue;
}
}
robj *decoded;
decoded = getDecodedObject(cc->argv[j]);
sds repr = sdscatrepr(sdsempty(),decoded->ptr, min(sdslen(decoded->ptr), 1024));

282
tests/modules/crash.c
View File

@ -21,19 +21,291 @@ void segfaultCrash(RedisModuleInfoCtx *ctx, int for_crash_report) {
*p = 'x';
}
int cmd_crash(RedisModuleCtx *ctx, RedisModuleString **argv, int argc) {
UNUSED(ctx);
UNUSED(argv);
UNUSED(argc);
RedisModule_Assert(0);
return REDISMODULE_OK;
}
int RedisModule_OnLoad(RedisModuleCtx *ctx, RedisModuleString **argv, int argc) {
REDISMODULE_NOT_USED(argv);
REDISMODULE_NOT_USED(argc);
if (RedisModule_Init(ctx,"infocrash",1,REDISMODULE_APIVER_1)
if (RedisModule_Init(ctx,"modulecrash",1,REDISMODULE_APIVER_1)
== REDISMODULE_ERR) return REDISMODULE_ERR;
RedisModule_Assert(argc == 1);
if (argc >= 1) {
if (!strcasecmp(RedisModule_StringPtrLen(argv[0], NULL), "segfault")) {
if (RedisModule_RegisterInfoFunc(ctx, segfaultCrash) == REDISMODULE_ERR) return REDISMODULE_ERR;
} else if(!strcasecmp(RedisModule_StringPtrLen(argv[0], NULL), "assert")) {
} else if (!strcasecmp(RedisModule_StringPtrLen(argv[0], NULL),"assert")) {
if (RedisModule_RegisterInfoFunc(ctx, assertCrash) == REDISMODULE_ERR) return REDISMODULE_ERR;
} else {
return REDISMODULE_ERR;
}
}
/* Create modulecrash.xadd command which is similar to xadd command.
* It will crash in the command handler to verify we print command tokens
* when hide-user-data-from-log config is enabled */
RedisModuleCommandInfo info = {
.version = REDISMODULE_COMMAND_INFO_VERSION,
.arity = -5,
.key_specs = (RedisModuleCommandKeySpec[]){
{
.notes = "UPDATE instead of INSERT because of the optional trimming feature",
.flags = REDISMODULE_CMD_KEY_RW | REDISMODULE_CMD_KEY_UPDATE,
.begin_search_type = REDISMODULE_KSPEC_BS_INDEX,
.bs.index.pos = 1,
.find_keys_type = REDISMODULE_KSPEC_FK_RANGE,
.fk.range = {0,1,0}
},
{0}
},
.args = (RedisModuleCommandArg[]){
{
.name = "key",
.type = REDISMODULE_ARG_TYPE_KEY,
.key_spec_index = 0
},
{
.name = "nomkstream",
.type = REDISMODULE_ARG_TYPE_PURE_TOKEN,
.token = "NOMKSTREAM",
.since = "6.2.0",
.flags = REDISMODULE_CMD_ARG_OPTIONAL
},
{
.name = "trim",
.type = REDISMODULE_ARG_TYPE_BLOCK,
.flags = REDISMODULE_CMD_ARG_OPTIONAL,
.subargs = (RedisModuleCommandArg[]){
{
.name = "strategy",
.type = REDISMODULE_ARG_TYPE_ONEOF,
.subargs = (RedisModuleCommandArg[]){
{
.name = "maxlen",
.type = REDISMODULE_ARG_TYPE_PURE_TOKEN,
.token = "MAXLEN",
},
{
.name = "minid",
.type = REDISMODULE_ARG_TYPE_PURE_TOKEN,
.token = "MINID",
.since = "6.2.0",
},
{0}
}
},
{
.name = "operator",
.type = REDISMODULE_ARG_TYPE_ONEOF,
.flags = REDISMODULE_CMD_ARG_OPTIONAL,
.subargs = (RedisModuleCommandArg[]){
{
.name = "equal",
.type = REDISMODULE_ARG_TYPE_PURE_TOKEN,
.token = "="
},
{
.name = "approximately",
.type = REDISMODULE_ARG_TYPE_PURE_TOKEN,
.token = "~"
},
{0}
}
},
{
.name = "threshold",
.type = REDISMODULE_ARG_TYPE_STRING,
.display_text = "threshold" /* Just for coverage, doesn't have a visible effect */
},
{
.name = "count",
.type = REDISMODULE_ARG_TYPE_INTEGER,
.token = "LIMIT",
.since = "6.2.0",
.flags = REDISMODULE_CMD_ARG_OPTIONAL
},
{0}
}
},
{
.name = "id-selector",
.type = REDISMODULE_ARG_TYPE_ONEOF,
.subargs = (RedisModuleCommandArg[]){
{
.name = "auto-id",
.type = REDISMODULE_ARG_TYPE_PURE_TOKEN,
.token = "*"
},
{
.name = "id",
.type = REDISMODULE_ARG_TYPE_STRING,
},
{0}
}
},
{
.name = "data",
.type = REDISMODULE_ARG_TYPE_BLOCK,
.flags = REDISMODULE_CMD_ARG_MULTIPLE,
.subargs = (RedisModuleCommandArg[]){
{
.name = "field",
.type = REDISMODULE_ARG_TYPE_STRING,
},
{
.name = "value",
.type = REDISMODULE_ARG_TYPE_STRING,
},
{0}
}
},
{0}
}
};
RedisModuleCommand *cmd;
if (RedisModule_CreateCommand(ctx,"modulecrash.xadd", cmd_crash,"write deny-oom random fast",0,0,0) == REDISMODULE_ERR)
return REDISMODULE_ERR;
cmd = RedisModule_GetCommand(ctx,"modulecrash.xadd");
if (RedisModule_SetCommandInfo(cmd, &info) == REDISMODULE_ERR)
return REDISMODULE_ERR;
/* Create a subcommand: modulecrash.parent sub
* It will crash in the command handler to verify we print subcommand name
* when hide-user-data-from-log config is enabled */
RedisModuleCommandInfo subcommand_info = {
.version = REDISMODULE_COMMAND_INFO_VERSION,
.arity = -5,
.key_specs = (RedisModuleCommandKeySpec[]){
{
.flags = REDISMODULE_CMD_KEY_RW | REDISMODULE_CMD_KEY_UPDATE,
.begin_search_type = REDISMODULE_KSPEC_BS_INDEX,
.bs.index.pos = 1,
.find_keys_type = REDISMODULE_KSPEC_FK_RANGE,
.fk.range = {0,1,0}
},
{0}
},
.args = (RedisModuleCommandArg[]){
{
.name = "key",
.type = REDISMODULE_ARG_TYPE_KEY,
.key_spec_index = 0
},
{
.name = "token",
.type = REDISMODULE_ARG_TYPE_PURE_TOKEN,
.token = "TOKEN",
.flags = REDISMODULE_CMD_ARG_OPTIONAL
},
{
.name = "data",
.type = REDISMODULE_ARG_TYPE_BLOCK,
.subargs = (RedisModuleCommandArg[]){
{
.name = "field",
.type = REDISMODULE_ARG_TYPE_STRING,
},
{
.name = "value",
.type = REDISMODULE_ARG_TYPE_STRING,
},
{0}
}
},
{0}
}
};
if (RedisModule_CreateCommand(ctx,"modulecrash.parent",NULL,"",0,0,0) == REDISMODULE_ERR)
return REDISMODULE_ERR;
RedisModuleCommand *parent = RedisModule_GetCommand(ctx,"modulecrash.parent");
if (RedisModule_CreateSubcommand(parent,"subcmd",cmd_crash,"",0,0,0) == REDISMODULE_ERR)
return REDISMODULE_ERR;
cmd = RedisModule_GetCommand(ctx,"modulecrash.parent|subcmd");
if (RedisModule_SetCommandInfo(cmd, &subcommand_info) == REDISMODULE_ERR)
return REDISMODULE_ERR;
/* Create modulecrash.zunion command which is similar to zunion command.
* It will crash in the command handler to verify we print command tokens
* when hide-user-data-from-log config is enabled */
RedisModuleCommandInfo zunioninfo = {
.version = REDISMODULE_COMMAND_INFO_VERSION,
.arity = -5,
.key_specs = (RedisModuleCommandKeySpec[]){
{
.flags = REDISMODULE_CMD_KEY_RO,
.begin_search_type = REDISMODULE_KSPEC_BS_INDEX,
.bs.index.pos = 1,
.find_keys_type = REDISMODULE_KSPEC_FK_KEYNUM,
.fk.keynum = {0,1,1}
},
{0}
},
.args = (RedisModuleCommandArg[]){
{
.name = "numkeys",
.type = REDISMODULE_ARG_TYPE_INTEGER,
},
{
.name = "key",
.type = REDISMODULE_ARG_TYPE_KEY,
.key_spec_index = 0,
.flags = REDISMODULE_CMD_ARG_MULTIPLE
},
{
.name = "weights",
.type = REDISMODULE_ARG_TYPE_INTEGER,
.token = "WEIGHTS",
.flags = REDISMODULE_CMD_ARG_OPTIONAL | REDISMODULE_CMD_ARG_MULTIPLE
},
{
.name = "aggregate",
.type = REDISMODULE_ARG_TYPE_ONEOF,
.token = "AGGREGATE",
.flags = REDISMODULE_CMD_ARG_OPTIONAL,
.subargs = (RedisModuleCommandArg[]){
{
.name = "sum",
.type = REDISMODULE_ARG_TYPE_PURE_TOKEN,
.token = "sum"
},
{
.name = "min",
.type = REDISMODULE_ARG_TYPE_PURE_TOKEN,
.token = "min"
},
{
.name = "max",
.type = REDISMODULE_ARG_TYPE_PURE_TOKEN,
.token = "max"
},
{0}
}
},
{
.name = "withscores",
.type = REDISMODULE_ARG_TYPE_PURE_TOKEN,
.token = "WITHSCORES",
.flags = REDISMODULE_CMD_ARG_OPTIONAL
},
{0}
}
};
if (RedisModule_CreateCommand(ctx,"modulecrash.zunion", cmd_crash,"readonly",0,0,0) == REDISMODULE_ERR)
return REDISMODULE_ERR;
cmd = RedisModule_GetCommand(ctx,"modulecrash.zunion");
if (RedisModule_SetCommandInfo(cmd, &zunioninfo) == REDISMODULE_ERR)
return REDISMODULE_ERR;
return REDISMODULE_OK;
}

70
tests/unit/moduleapi/crash.tcl
View File

@ -8,7 +8,7 @@ if {!$::valgrind} {
start_server {tags {"modules"}} {
r module load $testmodule assert
test {Test module crash when info crashes with an assertion } {
catch {r 0 info infocrash}
catch {r 0 info modulecrash}
set res [wait_for_log_messages 0 {"*=== REDIS BUG REPORT START: Cut & paste starting from here ===*"} 0 10 1000]
set loglines [lindex $res 1]
@ -34,7 +34,7 @@ if {!$::valgrind} {
start_server {tags {"modules"}} {
r module load $testmodule segfault
test {Test module crash when info crashes with a segfault} {
catch {r 0 info infocrash}
catch {r 0 info modulecrash}
set res [wait_for_log_messages 0 {"*=== REDIS BUG REPORT START: Cut & paste starting from here ===*"} 0 10 1000]
set loglines [lindex $res 1]
@ -60,4 +60,70 @@ if {!$::valgrind} {
assert_equal 1 [count_log_message 0 "=== REDIS BUG REPORT START: Cut & paste starting from here ==="]
}
}
start_server {tags {"modules"}} {
r module load $testmodule
# memcheck confuses sanitizer
r config set crash-memcheck-enabled no
test {Test command tokens are printed when hide-user-data-from-log is enabled (xadd)} {
r config set hide-user-data-from-log yes
catch {r 0 modulecrash.xadd key NOMKSTREAM MAXLEN ~ 1000 * a b}
wait_for_log_messages 0 {"*argv*0*: *modulecrash.xadd*"} 0 10 1000
wait_for_log_messages 0 {"*argv*1*: *redacted*"} 0 10 1000
wait_for_log_messages 0 {"*argv*2*: *NOMKSTREAM*"} 0 10 1000
wait_for_log_messages 0 {"*argv*3*: *MAXLEN*"} 0 10 1000
wait_for_log_messages 0 {"*argv*4*: *~*"} 0 10 1000
wait_for_log_messages 0 {"*argv*5*: *redacted*"} 0 10 1000
wait_for_log_messages 0 {"*argv*6*: *\**"} 0 10 1000
wait_for_log_messages 0 {"*argv*7*: *redacted*"} 0 10 1000
wait_for_log_messages 0 {"*argv*8*: *redacted*"} 0 10 1000
}
}
start_server {tags {"modules"}} {
r module load $testmodule
# memcheck confuses sanitizer
r config set crash-memcheck-enabled no
test {Test command tokens are printed when hide-user-data-from-log is enabled (zunion)} {
r config set hide-user-data-from-log yes
catch {r 0 modulecrash.zunion 2 zset1 zset2 WEIGHTS 1 2 WITHSCORES somedata}
wait_for_log_messages 0 {"*argv*0*: *modulecrash.zunion*"} 0 10 1000
wait_for_log_messages 0 {"*argv*1*: *redacted*"} 0 10 1000
wait_for_log_messages 0 {"*argv*2*: *redacted*"} 0 10 1000
wait_for_log_messages 0 {"*argv*3*: *redacted*"} 0 10 1000
wait_for_log_messages 0 {"*argv*4*: *WEIGHTS*"} 0 10 1000
wait_for_log_messages 0 {"*argv*5*: *redacted*"} 0 10 1000
wait_for_log_messages 0 {"*argv*6*: *redacted*"} 0 10 1000
wait_for_log_messages 0 {"*argv*7*: *WITHSCORES*"} 0 10 1000
# We don't expect arguments after WITHSCORE but just in case there
# is we rather not print it
wait_for_log_messages 0 {"*argv*8*: *redacted*"} 0 10 1000
}
}
start_server {tags {"modules"}} {
r module load $testmodule
# memcheck confuses sanitizer
r config set crash-memcheck-enabled no
test {Test subcommand name is printed when hide-user-data-from-log is enabled} {
r config set hide-user-data-from-log yes
catch {r 0 modulecrash.parent subcmd key TOKEN a b}
wait_for_log_messages 0 {"*argv*0*: *modulecrash.parent*"} 0 10 1000
wait_for_log_messages 0 {"*argv*1*: *subcmd*"} 0 10 1000
wait_for_log_messages 0 {"*argv*2*: *redacted*"} 0 10 1000
wait_for_log_messages 0 {"*argv*3*: *TOKEN*"} 0 10 1000
wait_for_log_messages 0 {"*argv*4*: *redacted*"} 0 10 1000
wait_for_log_messages 0 {"*argv*5*: *redacted*"} 0 10 1000
}
}
}