From ac3129543882bdb6e17c2953ec2be7c98ef840ba Mon Sep 17 00:00:00 2001 From: Roshan Khatri <117414976+roshkhatri@users.noreply.github.com> Date: Thu, 2 Feb 2023 12:12:16 -0800 Subject: [PATCH] Added fields to ACL LOG error entries for precise time logging (#11477) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- src/acl.c | 16 +++++++++++++++- src/commands.c | 5 ++++- src/commands/acl-log.json | 6 ++++++ tests/unit/acl.tcl | 22 ++++++++++++++++++++++ 4 files changed, 47 insertions(+), 2 deletions(-) diff --git a/src/acl.c b/src/acl.c index ba6b20716..6773403bd 100644 --- a/src/acl.c +++ b/src/acl.c @@ -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; diff --git a/src/commands.c b/src/commands.c index 6eb633114..5db70b487 100644 --- a/src/commands.c +++ b/src/commands.c @@ -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 diff --git a/src/commands/acl-log.json b/src/commands/acl-log.json index c599685dd..0e88ed68b 100644 --- a/src/commands/acl-log.json +++ b/src/commands/acl-log.json @@ -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", diff --git a/tests/unit/acl.tcl b/tests/unit/acl.tcl index f423bf111..71cf9ae43 100644 --- a/tests/unit/acl.tcl +++ b/tests/unit/acl.tcl @@ -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