研发同事反馈线上某redis cluster 某个hashmap异常, 应用日志中已经明确对于这个hashmap 特定的field1 hset成功了,但是其他的业务模块在hget 对应的field时,读不到对应数据。
根据业务提供的field到DB里面查询相应信息,查询redis
$redis-cli -p port -a -c 127.0.0.1:4410> hget hashmapa f1087507-c90f-4b08-b028-b3f14efc49f3/01 -> Redirected to slot [5265] located at IP:port (nil)注: HGET KEY_NAME FIELD_NAME 返回给定字段的值。如果给定的字段或 key 不存在时,返回 nil 。 这里需要注意,因为是redis cluster所以连接的使用切记加上-c进入cluster 模式
redis说你这根本就不存在这个field,但研发言之凿凿这个field一定是设置成功了的,redis说这个锅我可不背,这种时候最好的办法就是把证据(一口大黑锅)甩他脸上。
思索片刻之后,我们环境中cluster的从节点都是开启了aof持久化,那有无可能通过分析aof,来分析历史执行命令,从而定位问题?当然有可能。前提是需要考虑aof是否已经重写了,如果没有重写可以直接分析aof文件。
AOF的重写机制,分为手工触发和自动触发。 手动触发:调用bgrewriteaof命令。 自动触发:aof_current_size > auto-aof-rewrite-min-size && (aof_current_size - aof_base_size) / aof_base_size >= auto-aof-rewrite_percentage(默认100%)幸运的是 ,问题现象能够复现,那就没必要去分析不确定的历史aof,现在的问题就是如何在业务触发的时候,记录下这段时间redis的操作日志。 方法一: 可以使用redis本身的monitor 命令,但这一个繁忙的系统中,会对系统有一定的性能损耗(当然也可以选择在从节点执行 )。 方法二: 使用linux命令对aof文件进行tail -200f db.aof >res.log,也可以将这段时间内的命令记录下来。
此处我们采用方法二。接下来的任务问题就是cluster里面有非常多的分片,那我们要需要提前确定这个key目前在哪个分片上。
127.0.0.1:PORT> CLUSTER KEYSLOT userTokenMap (integer) 5265 127.0.0.1:PORT> CLUSTER SLOTS 4) 1) (integer) 2731 2) (integer) 5460 3) 1) "IP1" 2) (integer) PORT1 3) "e6e62c68eed8a9869b6e31aed5bac3291270688f" 4) 1) "IP2" 2) (integer) PORT2 3) "bedc109fa35821d379567649e2f3a2ded3771b73"通过cluster命令我们定位到了key所在分片。
在业务开始触发时开启收集日志,在复现结束后停止,并分析。下面是tail aof文件的结果(二进制)
这里可以看到值是存在的 IP:PORT> HGET userTokenMap "f1087507-c90f-4b08-b028-b3f14efc49f3 /01" "50017d18bf4a427e0111c1e7386c37f557ef39d3644d393d598c4fe8b986c1b30aa26f1b5f24e7394cb2ef99a0d5549d6980"分析日志发现,结果很明显 ,程序在使用这个field(f1087507-c90f-4b08-b028-b3f14efc49f3 /01)的时候会截取**/**部分, 默认的规则field都是无空格的,但是这个field 由于程序存取环节异常导致多了空格,从而引起应用其他模块使用该key的部分field异常,至此真相大白。
hset的时候拼接部分多了多了个空格
程序后续版本对field前半部分进行trim取消无效空格之后再拼接。