summaryrefslogtreecommitdiff
path: root/tests/unit/slowlog.tcl
Commit message (Collapse)AuthorAgeFilesLines
* reprocess command when client is unblocked on keys (#11012)ranshid2023-01-011-0/+22
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | *TL;DR* --------------------------------------- Following the discussion over the issue [#7551](https://github.com/redis/redis/issues/7551) We decided to refactor the client blocking code to eliminate some of the code duplications and to rebuild the infrastructure better for future key blocking cases. *In this PR* --------------------------------------- 1. reprocess the command once a client becomes unblocked on key (instead of running custom code for the unblocked path that's different than the one that would have run if blocking wasn't needed) 2. eliminate some (now) irrelevant code for handling unblocking lists/zsets/streams etc... 3. modify some tests to intercept the error in cases of error on reprocess after unblock (see details in the notes section below) 4. replace '$' on the client argv with current stream id. Since once we reprocess the stream XREAD we need to read from the last msg and not wait for new msg in order to prevent endless block loop. 5. Added statistics to the info "Clients" section to report the: * `total_blocking_keys` - number of blocking keys * `total_blocking_keys_on_nokey` - number of blocking keys which have at least 1 client which would like to be unblocked on when the key is deleted. 6. Avoid expiring unblocked key during unblock. Previously we used to lookup the unblocked key which might have been expired during the lookup. Now we lookup the key using NOTOUCH and NOEXPIRE to avoid deleting it at this point, so propagating commands in blocked.c is no longer needed. 7. deprecated command flags. We decided to remove the CMD_CALL_STATS and CMD_CALL_SLOWLOG and make an explicit verification in the call() function in order to decide if stats update should take place. This should simplify the logic and also mitigate existing issues: for example module calls which are triggered as part of AOF loading might still report stats even though they are called during AOF loading. *Behavior changes* --------------------------------------------------- 1. As this implementation prevents writing dedicated code handling unblocked streams/lists/zsets, since we now re-process the command once the client is unblocked some errors will be reported differently. The old implementation used to issue ``UNBLOCKED the stream key no longer exists`` in the following cases: - The stream key has been deleted (ie. calling DEL) - The stream and group existed but the key type was changed by overriding it (ie. with set command) - The key not longer exists after we swapdb with a db which does not contains this key - After swapdb when the new db has this key but with different type. In the new implementation the reported errors will be the same as if the command was processed after effect: **NOGROUP** - in case key no longer exists, or **WRONGTYPE** in case the key was overridden with a different type. 2. Reprocessing the command means that some checks will be reevaluated once the client is unblocked. For example, ACL rules might change since the command originally was executed and will fail once the client is unblocked. Another example is OOM condition checks which might enable the command to run and block but fail the command reprocess once the client is unblocked. 3. One of the changes in this PR is that no command stats are being updated once the command is blocked (all stats will be updated once the client is unblocked). This implies that when we have many clients blocked, users will no longer be able to get that information from the command stats. However the information can still be gathered from the client list. **Client blocking** --------------------------------------------------- the blocking on key will still be triggered the same way as it is done today. in order to block the current client on list of keys, the call to blockForKeys will still need to be made which will perform the same as it is today: * add the client to the list of blocked clients on each key * keep the key with a matching list node (position in the global blocking clients list for that key) in the client private blocking key dict. * flag the client with CLIENT_BLOCKED * update blocking statistics * register the client on the timeout table **Key Unblock** --------------------------------------------------- Unblocking a specific key will be triggered (same as today) by calling signalKeyAsReady. the implementation in that part will stay the same as today - adding the key to the global readyList. The reason to maintain the readyList (as apposed to iterating over all clients blocked on the specific key) is in order to keep the signal operation as short as possible, since it is called during the command processing. The main change is that instead of going through a dedicated code path that operates the blocked command we will just call processPendingCommandsAndResetClient. **ClientUnblock (keys)** --------------------------------------------------- 1. Unblocking clients on keys will be triggered after command is processed and during the beforeSleep 8. the general schema is: 9. For each key *k* in the readyList: ``` For each client *c* which is blocked on *k*: in case either: 1. *k* exists AND the *k* type matches the current client blocking type OR 2. *k* exists and *c* is blocked on module command OR 3. *k* does not exists and *c* was blocked with the flag unblock_on_deleted_key do: 1. remove the client from the list of clients blocked on this key 2. remove the blocking list node from the client blocking key dict 3. remove the client from the timeout list 10. queue the client on the unblocked_clients list 11. *NEW*: call processCommandAndResetClient(c); ``` *NOTE:* for module blocked clients we will still call the moduleUnblockClientByHandle which will queue the client for processing in moduleUnblockedClients list. **Process Unblocked clients** --------------------------------------------------- The process of all unblocked clients is done in the beforeSleep and no change is planned in that part. The general schema will be: For each client *c* in server.unblocked_clients: * remove client from the server.unblocked_clients * set back the client readHandler * continue processing the pending command and input buffer. *Some notes regarding the new implementation* --------------------------------------------------- 1. Although it was proposed, it is currently difficult to remove the read handler from the client while it is blocked. The reason is that a blocked client should be unblocked when it is disconnected, or we might consume data into void. 2. While this PR mainly keep the current blocking logic as-is, there might be some future additions to the infrastructure that we would like to have: - allow non-preemptive blocking of client - sometimes we can think that a new kind of blocking can be expected to not be preempt. for example lets imagine we hold some keys on disk and when a command needs to process them it will block until the keys are uploaded. in this case we will want the client to not disconnect or be unblocked until the process is completed (remove the client read handler, prevent client timeout, disable unblock via debug command etc...). - allow generic blocking based on command declared keys - we might want to add a hook before command processing to check if any of the declared keys require the command to block. this way it would be easier to add new kinds of key-based blocking mechanisms. Co-authored-by: Oran Agra <oran@redislabs.com> Signed-off-by: Ran Shidlansik <ranshid@amazon.com>
* Fix timing issue in slowlog redact test (#10614)Binbin2022-04-241-12/+13
| | | | | | | | | | | | | | | | | | * Fix timing issue in slowlog redact test This test failed once in my daily CI (test-sanitizer-address (clang)) ``` *** [err]: SLOWLOG - Some commands can redact sensitive fields in tests/unit/slowlog.tcl Expected 'migrate 127.0.0.1 25649 key 9 5000 AUTH2 (redacted) (redacted)' to match '* key 9 5000 AUTH (redacted)' (context: type eval line 12 cmd {assert_match {* key 9 5000 AUTH (redacted)} [lindex [lindex [r slowlog get] 1] 3]} proc ::test) ``` The reason is that with slowlog-log-slower-than 10000, slowlog get will have a chance to exceed 10ms. Change slowlog-log-slower-than from 10000 to -1, disable it. Also handles a same potentially problematic test above. This is actually the same timing issue as #10432. But also avoid repeated calls to `SLOWLOG GET`
* Redact ACL SETUSER arguments if the user has spaces (#9935)Madelyn Olson2021-12-131-2/+4
|
* slowlog get command supports passing in -1 to get all logs. (#9018)Binbin2021-06-141-1/+23
| | | This was already the case before this commit, but it wasn't clear / intended in the code, now it does.
* Improve test suite to handle external servers better. (#9033)Yossi Gottlieb2021-06-091-15/+16
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | This commit revives the improves the ability to run the test suite against external servers, instead of launching and managing `redis-server` processes as part of the test fixture. This capability existed in the past, using the `--host` and `--port` options. However, it was quite limited and mostly useful when running a specific tests. Attempting to run larger chunks of the test suite experienced many issues: * Many tests depend on being able to start and control `redis-server` themselves, and there's no clear distinction between external server compatible and other tests. * Cluster mode is not supported (resulting with `CROSSSLOT` errors). This PR cleans up many things and makes it possible to run the entire test suite against an external server. It also provides more fine grained controls to handle cases where the external server supports a subset of the Redis commands, limited number of databases, cluster mode, etc. The tests directory now contains a `README.md` file that describes how this works. This commit also includes additional cleanups and fixes: * Tests can now be tagged. * Tag-based selection is now unified across `start_server`, `tags` and `test`. * More information is provided about skipped or ignored tests. * Repeated patterns in tests have been extracted to common procedures, both at a global level and on a per-test file basis. * Cleaned up some cases where test setup was based on a previous test executing (a major anti-pattern that repeats itself in many places). * Cleaned up some cases where test teardown was not part of a test (in the future we should have dedicated teardown code that executes even when tests fail). * Fixed some tests that were flaky running on external servers.
* Hide migrate command from slowlog if they include auth (#8859)Madelyn Olson2021-05-191-4/+21
| | | Redact commands that include sensitive data from slowlog and monitor
* Fix SLOWLOG for blocked commands (#8632)Oran Agra2021-03-251-0/+16
| | | | | | | | | | | | | | | | | | | | | | | | | | | | | | | * SLOWLOG didn't record anything for blocked commands because the client was reset and argv was already empty. there was a fix for this issue specifically for modules, now it works for all blocked clients. * The original command argv (before being re-written) was also reset before adding the slowlog on behalf of the blocked command. * Latency monitor is now updated regardless of the slowlog flags of the command or its execution (their purpose is to hide sensitive info from the slowlog, not hide the fact the latency happened). * Latency monitor now uses real_cmd rather than c->cmd (which may be different if the command got re-written, e.g. GEOADD) Changes: * Unify shared code between slowlog insertion in call() and updateStatsOnUnblock(), hopefully prevent future bugs from happening due to the later being overlooked. * Reset CLIENT_PREVENT_LOGGING in resetClient rather than after command processing. * Add a test for SLOWLOG and BLPOP Notes: - real_cmd == c->lastcmd, except inside MULTI and Lua. - blocked commands never happen in these cases (MULTI / Lua) - real_cmd == c->cmd, except for when the command is rewritten (e.g. GEOADD) - blocked commands (currently) are never rewritten - other than the command's CLIENT_PREVENT_LOGGING, and the execution flag CLIENT_PREVENT_LOGGING, other cases that we want to avoid slowlog are on AOF loading (specifically CMD_CALL_SLOWLOG will be off when executed from execCommand that runs from an AOF)
* Redact slowlog entries for config with sensitive data. (#8584)Madelyn Olson2021-03-151-0/+16
| | | Redact config set requirepass/masterauth/masteruser from slowlog in addition to showing ACL commands without sensitive values.
* Rewritten commands are logged as their original command (#8006)Madelyn Olson2020-11-101-0/+35
| | | | | * Rewritten commands are logged as their original command Co-authored-by: Madelyn Olson <madelyneolson@gmail.com>
* Typo fix: entires -> entries (#8031)sundb2020-11-081-1/+1
|
* Test: fix slowlog test false positive.antirez2019-05-141-1/+3
| | | | | | | | | In fast systems "SLOWLOG RESET" is fast enough to don't be logged even when the time limit is "1" sometimes. Leading to false positives such as: [err]: SLOWLOG - can be disabled in tests/unit/slowlog.tcl Expected '1' to be equal to '0'
* Add test in slowlog.tclWuYunlong2018-07-131-0/+10
|
* SLOWLOG: log offending client address and name.antirez2017-06-151-1/+12
|
* Slowlog: don't log EXEC but just the executed commands.antirez2013-01-191-0/+12
| | | | | | | | | | The Redis Slow Log always used to log the slow commands executed inside a MULTI/EXEC block. However also EXEC was logged at the end, which is perfectly useless. Now EXEC is no longer logged and a test was added to test this behavior. This fixes issue #759.
* Limit memory used by big SLOWLOG entries.antirez2012-04-211-0/+17
| | | | | | | | | | | Two limits are added: 1) Up to SLOWLOG_ENTRY_MAX_ARGV arguments are logged. 2) Up to SLOWLOG_ENTRY_MAX_STRING bytes per argument are logged. 3) slowlog-max-len is set to 128 by default (was 1024). The number of remaining arguments / bytes is logged in the entry so that the user can understand better the nature of the logged command.
* solved a slow positive in the slow log test when the test is executed slowlyantirez2011-07-111-1/+1
|
* Added slowlog.tclantirez2011-07-011-0/+41