Added fields to ACL LOG error entries for precise time logging (#11477)

Added 3 fields to the ACL LOG - adds entry_id, timestamp_created and timestamp_last_updated, which updates similar existing log error entries. The pair - entry_id, timestamp_created is a unique identifier of this entry, in case the node dies and is restarted, it can detect that if it's a new series.

The primary use case of Unique id is to uniquely identify the error messages and not to detect if the server has restarted.

entry-id is the sequence number of the entry (starting at 0) since the server process started. Can also be used to check if items were "lost" if they fell between periods.
timestamp-created is the unix-time in ms at the time the entry was first created.
timestamp-last-updated is the unix-time in ms at the time the entry was last updated
Time_created gives the absolute time which better accounts for network time as compared to time since. It can also be older than 60 secs and presently there is no field that can display the original time of creation once the error entry is updated.
The reason of timestamp_last_updated field is that it provides a more precise value for the “last time” an error was seen where as, presently it is only in the 60 second period.

Co-authored-by: Madelyn Olson <madelyneolson@gmail.com>
This commit is contained in:
Roshan Khatri 2023-02-02 12:12:16 -08:00 committed by GitHub
parent 3b260149e0
commit ac31295438
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 47 additions and 2 deletions

View File

@ -53,6 +53,8 @@ list *UsersToLoad; /* This is a list of users found in the configuration file
list *ACLLog; /* Our security log, the user is able to inspect that
using the ACL LOG command .*/
long long ACLLogEntryCount = 0; /* Number of ACL log entries created */
static rax *commandId = NULL; /* Command name to id mapping */
static unsigned long nextid = 0; /* Next command id that has not been assigned */
@ -2433,6 +2435,9 @@ typedef struct ACLLogEntry {
sds username; /* User the client is authenticated with. */
mstime_t ctime; /* Milliseconds time of last update to this entry. */
sds cinfo; /* Client info (last client if updated). */
long long entry_id; /* The pair (entry_id, timestamp_created) is a unique identifier of this entry
* in case the node dies and is restarted, it can detect that if it's a new series. */
mstime_t timestamp_created; /* UNIX time in milliseconds at the time of this entry's creation. */
} ACLLogEntry;
/* This function will check if ACL entries 'a' and 'b' are similar enough
@ -2498,6 +2503,8 @@ void addACLLogEntry(client *c, int reason, int context, int argpos, sds username
le->reason = reason;
le->username = sdsdup(username ? username : c->user->name);
le->ctime = commandTimeSnapshot();
le->entry_id = ACLLogEntryCount;
le->timestamp_created = le->ctime;
if (object) {
le->object = object;
@ -2550,6 +2557,7 @@ void addACLLogEntry(client *c, int reason, int context, int argpos, sds username
} else {
/* Add it to our list of entries. We'll have to trim the list
* to its maximum size. */
ACLLogEntryCount++; /* Incrementing the entry_id count to make each record in the log unique. */
listAddNodeHead(ACLLog, le);
while(listLength(ACLLog) > server.acllog_max_len) {
listNode *ln = listLast(ACLLog);
@ -2884,7 +2892,7 @@ void aclCommand(client *c) {
mstime_t now = commandTimeSnapshot();
while (count-- && (ln = listNext(&li)) != NULL) {
ACLLogEntry *le = listNodeValue(ln);
addReplyMapLen(c,7);
addReplyMapLen(c,10);
addReplyBulkCString(c,"count");
addReplyLongLong(c,le->count);
@ -2919,6 +2927,12 @@ void aclCommand(client *c) {
addReplyDouble(c,age);
addReplyBulkCString(c,"client-info");
addReplyBulkCBuffer(c,le->cinfo,sdslen(le->cinfo));
addReplyBulkCString(c, "entry-id");
addReplyLongLong(c, le->entry_id);
addReplyBulkCString(c, "timestamp-created");
addReplyLongLong(c, le->timestamp_created);
addReplyBulkCString(c, "timestamp-last-updated");
addReplyLongLong(c, le->ctime);
}
} else if (!strcasecmp(sub,"dryrun") && c->argc >= 4) {
struct redisCommand *cmd;

View File

@ -4106,7 +4106,10 @@ struct redisCommandArg ACL_GETUSER_Args[] = {
/********** ACL LOG ********************/
/* ACL LOG history */
#define ACL_LOG_History NULL
commandHistory ACL_LOG_History[] = {
{"7.2.0","Added entry ID, timestamp created, and timestamp last updated."},
{0}
};
/* ACL LOG tips */
#define ACL_LOG_tips NULL

View File

@ -7,6 +7,12 @@
"arity": -2,
"container": "ACL",
"function": "aclCommand",
"history": [
[
"7.2.0",
"Added entry ID, timestamp created, and timestamp last updated."
]
],
"command_flags": [
"ADMIN",
"NOSCRIPT",

View File

@ -616,6 +616,28 @@ start_server {tags {"acl external:skip"}} {
# The test framework will detect a leak if any.
}
test {ACL LOG aggregates similar errors together and assigns unique entry-id to new errors} {
r ACL LOG RESET
r ACL setuser user1 >foo
assert_error "*WRONGPASS*" {r AUTH user1 doo}
set entry_id_initial_error [dict get [lindex [r ACL LOG] 0] entry-id]
set timestamp_created_original [dict get [lindex [r ACL LOG] 0] timestamp-created]
set timestamp_last_update_original [dict get [lindex [r ACL LOG] 0] timestamp-last-updated]
for {set j 0} {$j < 10} {incr j} {
assert_error "*WRONGPASS*" {r AUTH user1 doo}
}
set entry_id_lastest_error [dict get [lindex [r ACL LOG] 0] entry-id]
set timestamp_created_updated [dict get [lindex [r ACL LOG] 0] timestamp-created]
set timestamp_last_updated_after_update [dict get [lindex [r ACL LOG] 0] timestamp-last-updated]
assert {$entry_id_lastest_error eq $entry_id_initial_error}
assert {$timestamp_last_update_original < $timestamp_last_updated_after_update}
assert {$timestamp_created_original eq $timestamp_created_updated}
r ACL setuser user2 >doo
assert_error "*WRONGPASS*" {r AUTH user2 foo}
set new_error_entry_id [dict get [lindex [r ACL LOG] 0] entry-id]
assert {$new_error_entry_id eq $entry_id_lastest_error + 1 }
}
test {ACL LOG shows failed command executions at toplevel} {
r ACL LOG RESET
r ACL setuser antirez >foo on +set ~object:1234