deepflow icon indicating copy to clipboard operation
deepflow copied to clipboard

[BUG] Redis的RESP协议解析返回的数据包出现脏读

Open masterjyq opened this issue 1 year ago • 7 comments
trafficstars

Search before asking

  • [X] I had searched in the issues and found no similar feature requirement.

DeepFlow Component

Agent

What you expected to happen

在tracing 日志中发现 select 0 命令返回的数据是

-free=0 argv-mem=0 obl=0 oll=0 omem=0 tot-mem=20496 events=r cmd=ping user=default redir=-1 id=20855933 addr=172.30.90.128:36663 laddr=172.*.*.45:6379 fd=86 name= age=139442 idle=2630 flags=P db=0 sub=0 psub=3 multi=-1 qbuf=0 qbuf-free=0 argv-mem=0 obl=0

此数据是 client list 命令的一部分返回数据, 因为是-开头,就被识别成了错误 截图如下: 6e4655eba795870ba57c1e104a6d246

How to reproduce

此问题在Redis的tracing日志中偶发出现, 需要请求Redis 执行 clien list,info all,select 0 等命令.

DeepFlow version

kubectl exec -it -n deepflow deploy/deepflow-server -- deepflow-server -v 输出为:

2024/03/07 15:08:09 ENV K8S_NODE_NAME_FOR_DEEPFLOW=ro***06; K8S_NODE_IP_FOR_DEEPFLOW=10.*.*.139; K8S_POD_NAME_FOR_DEEPFLOW=release-name-deepflow-server-59b9cd58cf-mj4l4; K8S_POD_IP_FOR_DEEPFLOW=172.*.*.190; K8S_NAMESPACE_FOR_DEEPFLOW=deepflow
Name: deepflow-server community edition
Branch: v6.4.9
CommitID: 61501b27095c6e3409f8230161fe46b923590af9
RevCount: 9588
Compiler: go version go1.20.13 linux/amd64
CompileTime: 2024-01-19 02:04:13

kubectl exec -it -n deepflow ds/deepflow-agent -- deepflow-agent -v 输出为

9488-dbc714df297f59f70bf93075365638f052315c10
Name: deepflow-agent community edition
Branch: main
CommitId: dbc714df297f59f70bf93075365638f052315c10
RevCount: 9488
Compiler: rustc 1.73.0 (cc66ad468 2023-10-03)
CompileTime: 2023-12-29 10:06:14

DeepFlow agent list

No response

Kubernetes CNI

calico

Operation-System/Kernel version

"Kylin Linux Advanced Server V10 (Sword)"
4.19.90-24.4.v2101.ky10.aarch64

Anything else

No response

Are you willing to submit a PR?

  • [ ] Yes I am willing to submit a PR!

Code of Conduct

masterjyq avatar Mar 07 '24 07:03 masterjyq

抓包数据, 等待再次复现的时候提供

masterjyq avatar Mar 07 '24 07:03 masterjyq

如果 RESP 部分以 "-" 开始,那么这是一个 simple error ref: https://redis.io/docs/reference/protocol-spec/#simple-errors

不过也可能是分段导致,可以先抓包看看

rvql avatar Mar 11 '24 06:03 rvql

目前发现是并发较高, 同时返回数据过大, 有大量的Bulk String 的时候, 会出现这个现象, 正在复现抓包

masterjyq avatar Mar 11 '24 07:03 masterjyq

目前发现是并发较高, 同时返回数据过大, 有大量的Bulk String 的时候, 会出现这个现象, 正在复现抓包

如果当时的环境还在可以确认一下误报的日志上一条日志的内容是不是和误报这条是连续的

rvql avatar Mar 11 '24 10:03 rvql

抓到包了, 目前错误是这样的, 先后执行了 LRANGE 和 PEXPIRE image image PEXPIRE 的 返回结果在LRANG的结果中 image 然后agent 截取成了 -4}, 是bulkstring 中的一部分 image image

masterjyq avatar Mar 25 '24 06:03 masterjyq

从图中可以看到是有 TCP 分段的,我判断是正好在 -4 之前发生了截断,导致第二部分被当成 simple error 识别了

由于我们不支持 TCP 重组,这样的情况是会误报的

rvql avatar Mar 25 '24 09:03 rvql

从图中可以看到是有 TCP 分段的,我判断是正好在 -4 之前发生了截断,导致第二部分被当成 simple error 识别了

由于我们不支持 TCP 重组,这样的情况是会误报的

还发现 client K8s Node 层的结果是正确的, 但是 Server 是错误的 image

masterjyq avatar Mar 27 '24 02:03 masterjyq