|
| 1 | +Logging and validating the underlying RESP stream |
| 2 | +=== |
| 3 | + |
| 4 | +Sometimes (rarely) there is a question over the validity of the RESP stream from a server (especially when using proxies |
| 5 | +or a "redis-like-but-not-actually-redis" server), and it is hard to know whether the *data sent* was bad, vs |
| 6 | +the client library tripped over the data. |
| 7 | + |
| 8 | +To help with this, an experimental API exists to help log and validate RESP streams. This API is not intended |
| 9 | +for routine use (and may change at any time), but can be useful for diagnosing problems. |
| 10 | + |
| 11 | +For example, consider we have the following load test which (on some setup) causes a failure with some |
| 12 | +degree of reliability (even if you need to run it 6 times to see a failure): |
| 13 | + |
| 14 | +``` c# |
| 15 | +// connect |
| 16 | +Console.WriteLine("Connecting..."); |
| 17 | +var options = ConfigurationOptions.Parse(ConnectionString); |
| 18 | +await using var muxer = await ConnectionMultiplexer.ConnectAsync(options); |
| 19 | +var db = muxer.GetDatabase(); |
| 20 | + |
| 21 | +// load |
| 22 | +RedisKey testKey = "marc_abc"; |
| 23 | +await db.KeyDeleteAsync(testKey); |
| 24 | +Console.WriteLine("Writing..."); |
| 25 | +for (int i = 0; i < 100; i++) |
| 26 | +{ |
| 27 | + // sync every 50 iterations (pipeline the rest) |
| 28 | + var flags = (i % 50) == 0 ? CommandFlags.None : CommandFlags.FireAndForget; |
| 29 | + await db.SetAddAsync(testKey, Guid.NewGuid().ToString(), flags); |
| 30 | +} |
| 31 | + |
| 32 | +// fetch |
| 33 | +Console.WriteLine("Reading..."); |
| 34 | +int count = 0; |
| 35 | +for (int i = 0; i < 10; i++) |
| 36 | +{ |
| 37 | + // this is deliberately not using SCARD |
| 38 | + // (to put load on the inbound) |
| 39 | + count += (await db.SetMembersAsync(testKey)).Length; |
| 40 | +} |
| 41 | +Console.WriteLine("all done"); |
| 42 | +``` |
| 43 | + |
| 44 | +## Logging RESP streams |
| 45 | + |
| 46 | +When this fails, it will not be obvious exactly who is to blame. However, we can ask for the data streams |
| 47 | +to be logged to the local file-system. |
| 48 | + |
| 49 | +**Obviously, this may leave data on disk, so this may present security concerns if used with production data; use |
| 50 | +this feature sparingly, and clean up after yourself!** |
| 51 | + |
| 52 | +``` c# |
| 53 | +// connect |
| 54 | +Console.WriteLine("Connecting..."); |
| 55 | +var options = ConfigurationOptions.Parse(ConnectionString); |
| 56 | +LoggingTunnel.LogToDirectory(options, @"C:\Code\RedisLog"); // <=== added! |
| 57 | +await using var muxer = await ConnectionMultiplexer.ConnectAsync(options); |
| 58 | +... |
| 59 | +``` |
| 60 | + |
| 61 | +This API is marked `[Obsolete]` simply to discourage usage, but you can ignore this warning once you |
| 62 | +understand what it is saying (using `#pragma warning disable CS0618` if necessary). |
| 63 | + |
| 64 | +This will update the `ConfigurationOptions` with a custom `Tunnel` that performs file-based mirroring |
| 65 | +of the RESP streams. If `Ssl` is enabled on the `ConfigurationOptions`, the `Tunnel` will *take over that responsibility* |
| 66 | +(so that the unencrypted data can be logged), and will *disable* `Ssl` on the `ConfigurationOptions` - but TLS |
| 67 | +will still be used correctly. |
| 68 | + |
| 69 | +If we run our code, we will see that 2 files are written per connection ("in" and "out"); if you are using RESP2 (the default), |
| 70 | +then 2 connections are usually established (one for regular "interactive" commands, and one for pub/sub messages), so this will |
| 71 | +typically create 4 files. |
| 72 | + |
| 73 | +## Validating RESP streams |
| 74 | + |
| 75 | +RESP is *mostly* text, so a quick eyeball can be achieved using any text tool; an "out" file will typically start: |
| 76 | + |
| 77 | +``` txt |
| 78 | +$6 |
| 79 | +CLIENT |
| 80 | +$7 |
| 81 | +SETNAME |
| 82 | +... |
| 83 | +``` |
| 84 | + |
| 85 | +and an "in" file will typically start: |
| 86 | + |
| 87 | +``` txt |
| 88 | ++OK |
| 89 | ++OK |
| 90 | ++OK |
| 91 | +... |
| 92 | +``` |
| 93 | + |
| 94 | +This is the start of the handshakes for identifying the client to the redis server, and the server acknowledging this (if |
| 95 | +you have authentication enabled, there will be a `AUTH` command first, or `HELLO` on RESP3). |
| 96 | + |
| 97 | +If there is a failure, you obviously don't want to manually check these files. Instead, an API exists to validate RESP streams: |
| 98 | + |
| 99 | +``` c# |
| 100 | +var messages = await LoggingTunnel.ValidateAsync(@"C:\Code\RedisLog"); |
| 101 | +Console.WriteLine($"{messages} RESP fragments validated"); |
| 102 | +``` |
| 103 | + |
| 104 | +If the RESP streams are *not* valid, an exception will provide further details. |
| 105 | + |
| 106 | +**An exception here is strong evidence that there is a fault either in the redis server, or an intermediate proxy**. |
| 107 | + |
| 108 | +Conversely, if the library reported a protocol failure but the validation step here *does not* report an error, then |
| 109 | +that is strong evidence of a library error; [**please report this**](https://github.com/StackExchange/StackExchange.Redis/issues/new) (with details). |
| 110 | + |
| 111 | +You can also *replay* the conversation locally, seeing the individual requests and responses: |
| 112 | + |
| 113 | +``` c# |
| 114 | +var messages = await LoggingTunnel.ReplayAsync(@"C:\Code\RedisLog", (cmd, resp) => |
| 115 | +{ |
| 116 | + if (cmd.IsNull) |
| 117 | + { |
| 118 | + // out-of-band/"push" response |
| 119 | + Console.WriteLine("<< " + LoggingTunnel.DefaultFormatResponse(resp)); |
| 120 | + } |
| 121 | + else |
| 122 | + { |
| 123 | + Console.WriteLine(" > " + LoggingTunnel.DefaultFormatCommand(cmd)); |
| 124 | + Console.WriteLine(" < " + LoggingTunnel.DefaultFormatResponse(resp)); |
| 125 | + } |
| 126 | +}); |
| 127 | +Console.WriteLine($"{messages} RESP commands validated"); |
| 128 | +``` |
| 129 | + |
| 130 | +The `DefaultFormatCommand` and `DefaultFormatResponse` methods are provided for convenience, but you |
| 131 | +can perform your own formatting logic if required. If a RESP erorr is encountered in the response to |
| 132 | +a particular message, the callback will still be invoked to indicate that error. For example, after deliberately |
| 133 | +introducing an error into the captured file, we might see: |
| 134 | + |
| 135 | +``` txt |
| 136 | + > CLUSTER NODES |
| 137 | + < -ERR This instance has cluster support disabled |
| 138 | + > GET __Booksleeve_TieBreak |
| 139 | + < (null) |
| 140 | + > ECHO ... |
| 141 | + < -Invalid bulk string terminator |
| 142 | +Unhandled exception. StackExchange.Redis.RedisConnectionException: Invalid bulk string terminator |
| 143 | +``` |
| 144 | + |
| 145 | +The `-ERR` message is not a problem - that's normal and simply indicates that this is not a redis cluster; however, the |
| 146 | +final pair is an `ECHO` request, for which the corresponding response was invalid. This information is useful for finding |
| 147 | +out what happened. |
| 148 | + |
| 149 | +Emphasis: this API is not intended for common/frequent usage; it is intended only to assist validating the underlying |
| 150 | +RESP stream. |
0 commit comments