Skip to content

Commit 0d27d31

Browse files
YueTang-Vanessaranshid
authored and
RayaCoo
committed
Redact protocol error log when hide-user-data-from-log enabled (valkey-io#1889)
In this code logic: https://github.com/valkey-io/valkey/blob/unstable/src/networking.c#L2767-L2773, `c->querybuf + c->qb_pos` may also include user data. Update the log message when config `hide-user-data-from-log` is enabled. --------- Signed-off-by: VanessaTang <yuetan@amazon.com> Signed-off-by: Ran Shidlansik <ranshid@amazon.com> Co-authored-by: Ran Shidlansik <ranshid@amazon.com>
1 parent da32443 commit 0d27d31

File tree

5 files changed

+142
-15
lines changed

5 files changed

+142
-15
lines changed

‎src/expire.c‎

Lines changed: 101 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,69 @@
3737

3838
#include "server.h"
3939

40+
41+
#define EVPOOL_SIZE 20
42+
#define EVPOOL_CACHED_SDS_SIZE 255
43+
struct expirePoolEntry {
44+
long long expiretime; /* Absolute expiration time */
45+
robj *entry; /* The entry with expire time */
46+
};
47+
48+
static struct expirePoolEntry **ExpirePools;
49+
50+
/* Create an array of expire pools, one for each database.
51+
* This allows us to separately track expiration candidates for each DB. */
52+
static struct expirePoolEntry **ExpirePools;
53+
54+
void expirePoolAlloc(void) {
55+
int dbnum = server.dbnum;
56+
57+
ExpirePools = zmalloc(sizeof(struct expirePoolEntry *) * dbnum);
58+
59+
for (int i = 0; i < dbnum; i++) {
60+
ExpirePools[i] = zmalloc(sizeof(struct expirePoolEntry) * EVPOOL_SIZE);
61+
for (int j = 0; j < EVPOOL_SIZE; j++) {
62+
ExpirePools[i][j].expiretime = 0;
63+
ExpirePools[i][j].entry = NULL;
64+
}
65+
}
66+
}
67+
68+
void expirePoolPopulate(serverDb *db, robj *val, long long expiretime) {
69+
struct expirePoolEntry *pool = ExpirePools[db->id];
70+
int k;
71+
72+
k = 0;
73+
while (k < EVPOOL_SIZE && pool[k].entry && pool[k].expiretime < expiretime) k++;
74+
75+
/* If we can't insert (all slots filled with sooner-to-expire entries), return */
76+
if (k == 0 && pool[EVPOOL_SIZE - 1].entry != NULL) {
77+
return;
78+
} else if (k < EVPOOL_SIZE && pool[k].entry == NULL) {
79+
/* Inserting into empty position. No setup needed before insert. */
80+
} else {
81+
/* Inserting in the middle. Now k points to the first element
82+
* with expire time greater than the element to insert. */
83+
if (pool[EVPOOL_SIZE - 1].entry == NULL) {
84+
/* Free space on the right? Insert at k shifting
85+
* all the elements from k to end to the right. */
86+
memmove(pool + k + 1, pool + k, sizeof(pool[0]) * (EVPOOL_SIZE - k - 1));
87+
} else {
88+
/* No free space on right? Insert at k-1 */
89+
k--;
90+
/* Shift all elements on the left of k (included) to the
91+
* left, so we discard the element with smallest expire time. */
92+
if (pool[0].entry) decrRefCount(pool[0].entry);
93+
memmove(pool, pool + 1, sizeof(pool[0]) * k);
94+
}
95+
}
96+
97+
/* Store the entry and increment its refcount */
98+
pool[k].entry = val;
99+
incrRefCount(val);
100+
pool[k].expiretime = expiretime;
101+
}
102+
40103
/*-----------------------------------------------------------------------------
41104
* Incremental collection of expired keys.
42105
*
@@ -135,7 +198,8 @@ typedef struct {
135198
void expireScanCallback(void *privdata, void *entry) {
136199
robj *val = entry;
137200
expireScanData *data = privdata;
138-
long long ttl = objectGetExpire(val) - data->now;
201+
long long expiretime = objectGetExpire(val);
202+
long long ttl = expiretime - data->now;
139203
if (activeExpireCycleTryExpire(data->db, val, data->now)) {
140204
data->expired++;
141205
/* Propagate the DEL command */
@@ -145,6 +209,9 @@ void expireScanCallback(void *privdata, void *entry) {
145209
/* We want the average TTL of keys yet not expired. */
146210
data->ttl_sum += ttl;
147211
data->ttl_samples++;
212+
213+
/* Try to add this entry to the expiration pool for future expiration */
214+
expirePoolPopulate(data->db, val, expiretime);
148215
}
149216
data->sampled++;
150217
}
@@ -252,6 +319,39 @@ void activeExpireCycle(int type) {
252319

253320
if (kvstoreSize(db->expires)) dbs_performed++;
254321

322+
/* First, try to expire keys from the expire pool */
323+
struct expirePoolEntry *pool = ExpirePools[db->id];
324+
long long now = mstime();
325+
int expired_from_pool = 0;
326+
327+
/* Traverse from back to front, stop when we find a non-expired key */
328+
for (int i = EVPOOL_SIZE - 1; i >= 0; i--) {
329+
if (pool[i].entry == NULL) continue;
330+
if (pool[i].expiretime <= now) {
331+
/* Key is expired, try to expire it */
332+
if (activeExpireCycleTryExpire(db, pool[i].entry, now)) {
333+
expired_from_pool++;
334+
/* Propagate the DEL command */
335+
postExecutionUnitOperations();
336+
}
337+
338+
/* Clean up the pool entry */
339+
decrRefCount(pool[i].entry);
340+
pool[i].entry = NULL;
341+
pool[i].expiretime = 0;
342+
} else {
343+
/* Since we're traversing from back to front and keys are sorted by expire time,
344+
* if we find a non-expired key, all keys before it are also not expired */
345+
break;
346+
}
347+
}
348+
349+
/* If we found expired keys in the pool, update stats */
350+
if (expired_from_pool > 0) {
351+
total_expired += expired_from_pool;
352+
total_sampled += expired_from_pool;
353+
}
354+
255355
/* Continue to expire if at the end of the cycle there are still
256356
* a big percentage of keys to expire, compared to the number of keys
257357
* we scanned. The percentage, stored in config_cycle_acceptable_stale

‎src/networking.c‎

Lines changed: 17 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -2764,24 +2764,27 @@ static void setProtocolError(const char *errstr, client *c) {
27642764
/* Sample some protocol to given an idea about what was inside. */
27652765
char buf[256];
27662766
buf[0] = '\0';
2767-
if (c->querybuf && sdslen(c->querybuf) - c->qb_pos < PROTO_DUMP_LEN) {
2768-
snprintf(buf, sizeof(buf), "Query buffer during protocol error: '%s'", c->querybuf + c->qb_pos);
2769-
} else if (c->querybuf) {
2770-
snprintf(buf, sizeof(buf), "Query buffer during protocol error: '%.*s' (... more %zu bytes ...) '%.*s'",
2771-
PROTO_DUMP_LEN / 2, c->querybuf + c->qb_pos, sdslen(c->querybuf) - c->qb_pos - PROTO_DUMP_LEN,
2772-
PROTO_DUMP_LEN / 2, c->querybuf + sdslen(c->querybuf) - PROTO_DUMP_LEN / 2);
2773-
}
2767+
if (server.hide_user_data_from_log) {
2768+
snprintf(buf, sizeof(buf), "*redacted*");
2769+
} else {
2770+
if (c->querybuf && sdslen(c->querybuf) - c->qb_pos < PROTO_DUMP_LEN) {
2771+
snprintf(buf, sizeof(buf), "'%s'", c->querybuf + c->qb_pos);
2772+
} else if (c->querybuf) {
2773+
snprintf(buf, sizeof(buf), "'%.*s' (... more %zu bytes ...) '%.*s'",
2774+
PROTO_DUMP_LEN / 2, c->querybuf + c->qb_pos, sdslen(c->querybuf) - c->qb_pos - PROTO_DUMP_LEN,
2775+
PROTO_DUMP_LEN / 2, c->querybuf + sdslen(c->querybuf) - PROTO_DUMP_LEN / 2);
2776+
}
27742777

2775-
/* Remove non printable chars. */
2776-
char *p = buf;
2777-
while (*p != '\0') {
2778-
if (!isprint(*p)) *p = '.';
2779-
p++;
2778+
/* Remove non printable chars. */
2779+
char *p = buf;
2780+
while (*p != '\0') {
2781+
if (!isprint(*p)) *p = '.';
2782+
p++;
2783+
}
27802784
}
2781-
27822785
/* Log all the client and protocol info. */
27832786
int loglevel = (c->flag.primary) ? LL_WARNING : LL_VERBOSE;
2784-
serverLog(loglevel, "Protocol error (%s) from client: %s. %s", errstr, client, buf);
2787+
serverLog(loglevel, "Protocol error (%s) from client: %s. Query buffer: %s", errstr, client, buf);
27852788
sdsfree(client);
27862789
}
27872790
c->flag.close_after_reply = 1;

‎src/server.c‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2844,6 +2844,7 @@ void initServer(void) {
28442844
server.db[j].avg_ttl = 0;
28452845
}
28462846
evictionPoolAlloc(); /* Initialize the LRU keys pool. */
2847+
expirePoolAlloc(); /* Initialize the expire pools. */
28472848
/* Note that server.pubsub_channels was chosen to be a kvstore (with only one dict, which
28482849
* seems odd) just to make the code cleaner by making it be the same type as server.pubsubshard_channels
28492850
* (which has to be kvstore), see pubsubtype.serverPubSubChannels */

‎src/server.h‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3555,6 +3555,8 @@ void handleBlockedClientsTimeout(void);
35553555
int clientsCronHandleTimeout(client *c, mstime_t now_ms);
35563556

35573557
/* expire.c -- Handling of expired keys */
3558+
void expirePoolAlloc(void);
3559+
void expirePoolPopulate(serverDb *db, robj *val, long long expiretime);
35583560
void activeExpireCycle(int type);
35593561
void expireReplicaKeys(void);
35603562
void rememberReplicaKeyWithExpire(serverDb *db, robj *key);

‎tests/integration/logging.tcl‎

Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -109,6 +109,27 @@ if {!$::valgrind} {
109109
assert_equal "PONG" [r ping]
110110
}
111111
}
112+
113+
# test hide-user-data-from-log
114+
set server_path [tmpdir server5.log]
115+
start_server [list overrides [list dir $server_path crash-memcheck-enabled no hide-user-data-from-log no]] {
116+
test "Config hide-user-data-from-log is off" {
117+
r write "*3\r\n\$3\r\nSET\r\n\$1\r\nx\r\n\$blabla\r\n"
118+
r flush
119+
catch {r debug segfault}
120+
wait_for_log_messages 0 {"*Query buffer: *\$blabla*"} 0 10 1000
121+
}
122+
}
123+
124+
set server_path [tmpdir server6.log]
125+
start_server [list overrides [list dir $server_path crash-memcheck-enabled no hide-user-data-from-log yes]] {
126+
test "Config hide-user-data-from-log is on" {
127+
r write "*3\r\n\$3\r\nSET\r\n\$1\r\nx\r\n\$blabla\r\n"
128+
r flush
129+
catch {r debug segfault}
130+
wait_for_log_messages 0 {"*Query buffer: *redacted*"} 0 10 1000
131+
}
132+
}
112133
}
113134

114135
# test DEBUG ASSERT

0 commit comments

Comments
 (0)