Request packets after the first http2 request packet of the same tcp flow are lost

[huaixia777]

Describe the bug
Request packets after the first http2 request packet of the same tcp stream are lost

To Reproduce
Steps to reproduce the behavior:

1. Run ecapture and wireshark
2. Use a browser to access the nginx server and construct http2 packets
3. In the same tcp flow, all request packets after the first one are lost

Screenshots
wireshark

ecapture: When the http2 request packet is lost, an error message "[http2 response] Dump HTTP2 Frame error: connection error: COMPRESSION_ERROR" is displayed

[root@xxx]# ./bin/ecapture-ctyun tls
2025-02-24T15:12:43+08:00 INF AppName="eCapture(旁观者)"
2025-02-24T15:12:43+08:00 INF HomePage=https://ecapture.cc
2025-02-24T15:12:43+08:00 INF Repository=https://github.com/gojue/ecapture
2025-02-24T15:12:43+08:00 INF Author="CFC4N <cfc4ncs@gmail.com>"
2025-02-24T15:12:43+08:00 INF Description="Capturing SSL/TLS plaintext without a CA certificate using eBPF. Supported on Linux/Android kernels for amd64/arm64."
2025-02-24T15:12:43+08:00 INF Version=linux_amd64:v0.9.3-20250210-dcfc3cf:x86_64
2025-02-24T15:12:43+08:00 INF Listen=localhost:28256
2025-02-24T15:12:43+08:00 INF eCapture running logs logger=
2025-02-24T15:12:43+08:00 INF the file handler that receives the captured event eventCollector=
2025-02-24T15:12:43+08:00 INF listen=localhost:28256
2025-02-24T15:12:43+08:00 INF https server starting...You can upgrade the configuration file via the HTTP interface.
2025-02-24T15:12:43+08:00 WRN Kernel version is less than 5.2, Process filtering parameters do not take effect such as pid/uid. kernel=4.19.90
2025-02-24T15:12:43+08:00 INF Kernel Info=4.19.90 Pid=1790837
2025-02-24T15:12:43+08:00 INF BTF bytecode mode: non-CORE. btfMode=0
2025-02-24T15:12:43+08:00 INF master key keylogger has been set. eBPFProgramType=Text keylogger=
2025-02-24T15:12:43+08:00 INF module initialization. isReload=false moduleName=EBPFProbeOPENSSL
2025-02-24T15:12:43+08:00 INF Module.Run()
2025-02-24T15:12:43+08:00 INF origin versionKey="openssl 1.1.1f" versionKeyLower="openssl 1.1.1f"
2025-02-24T15:12:43+08:00 INF OpenSSL/BoringSSL version found Android=false library version="openssl 1.1.1f"
2025-02-24T15:12:43+08:00 INF Hook masterKey function ElfType=2 Functions=["SSL_get_wbio","SSL_in_before","SSL_do_handshake"] binrayPath=/lib64/libssl.so.1.1
2025-02-24T15:12:43+08:00 WRN Your kernel version is less than 5.2, GlobalVar is disabled, the following parameters will be ignored:[target_pid, target_uid, target_port]
2025-02-24T15:12:43+08:00 INF setupManagers eBPFProgramType=Text
2025-02-24T15:12:43+08:00 INF BPF bytecode file is matched. bpfFileName=user/bytecode/openssl_1_1_1d_kern_noncore_less52.o
2025-02-24T15:12:44+08:00 INF perfEventReader created mapSize(MB)=4
2025-02-24T15:12:44+08:00 INF perfEventReader created mapSize(MB)=4
2025-02-24T15:12:44+08:00 INF module started successfully. isReload=false moduleName=EBPFProbeOPENSSL
2025-02-24T15:13:01+08:00 ??? UUID:680600_680600_nginx_5_1_192.168.20.38:50704-192.168.10.41:4443, Name:HTTP2Response, Type:4, Length:577

Frame Type      =>      SETTINGS
Frame StreamID  =>      0

Frame Type      =>      WINDOW_UPDATE
Frame StreamID  =>      0

Frame Type      =>      SETTINGS
Frame StreamID  =>      0

Frame Type      =>      HEADERS
Frame StreamID  =>      1
header field ":status" = "200"
header field "server" = "nginx/1.21.5"
header field "date" = "Mon, 24 Feb 2025 07:12:59 GMT"
header field "content-type" = "text/plain"
header field "content-length" = "12"
header field "last-modified" = "Mon, 23 Dec 2024 02:20:35 GMT"
header field "etag" = "\"6768c8f3-c\""
header field "accept-ranges" = "bytes"

Frame Type      =>      DATA
Frame StreamID  =>      1
hello world

2025-02-24T15:13:01+08:00 ??? UUID:680600_680600_nginx_5_0_192.168.20.38:50704-192.168.10.41:4443, Name:HTTP2Request, Type:2, Length:1269

Frame Type      =>      SETTINGS
Frame StreamID  =>      0

Frame Type      =>      WINDOW_UPDATE
Frame StreamID  =>      0

Frame Type      =>      HEADERS
Frame StreamID  =>      1
header field ":method" = "GET"
header field ":authority" = "192.168.10.41:4443"
header field ":scheme" = "https"
header field ":path" = "/1.txt"
header field "cache-control" = "max-age=0"
header field "sec-ch-ua" = "\"Not(A:Brand\";v=\"99\", \"Microsoft Edge\";v=\"133\", \"Chromium\";v=\"133\""
header field "sec-ch-ua-mobile" = "?0"
header field "sec-ch-ua-platform" = "\"Windows\""
header field "upgrade-insecure-requests" = "1"
header field "user-agent" = "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/133.0.0.0 Safari/537.36 Edg/133.0.0.0"
header field "accept" = "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7"
header field "sec-fetch-site" = "none"
header field "sec-fetch-mode" = "navigate"
header field "sec-fetch-user" = "?1"
header field "sec-fetch-dest" = "document"
header field "accept-encoding" = "gzip, deflate, br, zstd"
header field "accept-language" = "zh-CN,zh;q=0.9,en;q=0.8,en-GB;q=0.7,en-US;q=0.6"
header field "priority" = "u=0, i"

Frame Type      =>      SETTINGS
Frame StreamID  =>      0

2025/02/24 15:13:02 [http2 response] Dump HTTP2 Frame error: connection error: COMPRESSION_ERROR
2025-02-24T15:13:02+08:00 ??? UUID:680600_680600_nginx_5_1_0.0.0.0:0-0.0.0.0:0, Name:HTTP2Response, Type:4, Length:440

Frame Type      =>      HEADERS
Frame StreamID  =>      3
header field ":status" = "200"
header field "server" = "nginx/1.21.5"
header field "date" = "Mon, 24 Feb 2025 07:13:01 GMT"
header field "content-type" = "text/plain"
header field "content-length" = "12"
header field "last-modified" = "Mon, 23 Dec 2024 02:20:35 GMT"
header field "etag" = "\"6768c8f3-c\""
header field "accept-ranges" = "bytes"

Frame Type      =>      DATA
Frame StreamID  =>      3
hello world

2025/02/24 15:13:07 [http2 response] Dump HTTP2 Frame error: connection error: COMPRESSION_ERROR
2025-02-24T15:13:07+08:00 ??? UUID:680600_680600_nginx_5_1_0.0.0.0:0-0.0.0.0:0, Name:HTTP2Response, Type:4, Length:440

Frame Type      =>      HEADERS
Frame StreamID  =>      5
header field ":status" = "200"
header field "server" = "nginx/1.21.5"
header field "date" = "Mon, 24 Feb 2025 07:13:06 GMT"
header field "content-type" = "text/plain"
header field "content-length" = "12"
header field "last-modified" = "Mon, 23 Dec 2024 02:20:35 GMT"
header field "etag" = "\"6768c8f3-c\""
header field "accept-ranges" = "bytes"

Frame Type      =>      DATA
Frame StreamID  =>      5
hello world

^C2025-02-24T15:13:23+08:00 INF module close.
2025-02-24T15:13:23+08:00 INF Module closed,message recived from Context
2025-02-24T15:13:23+08:00 INF iModule module close
2025-02-24T15:13:23+08:00 INF bye bye.

I observed that when the code matches the http2 request message, it determines whether there is "PRI * HTTP/2.0\r\n\r\nSM\r\n\r\n" field, but in the same tcp flow, there is only "PRI * HTTP/2.0\r\n\r\nSM\r\n\r\n" field at the beginning. Is this the reason that causes the loss of the request message?

[yuweizzz]

Can you try #742 to see if it has an error log still? The loss of the request message may be another question.

[huaixia777]

Can you try #742 to see if it has an error log still? The loss of the request message may be another question.

I tried #742 and the problem with lost request messages still persists, and the response message can always be caught

[yuweizzz]

The readframe function may treat those frames as illegal ones; need to fix via a new patch.

[yuweizzz]

It is hard to fix this problem, the better solution is use pcap mode. see #745 .

[huaixia777]

It is hard to fix this problem, the better solution is use pcap mode. see #745 .

Thank you for your time!
I read your comment in #745 and was a little confused.
In your second example, you said that the new stream belongs to a different event worker than the first stream on the same tcp connection, and the different event workers cannot share the hpack decoder.

But in second example it seems that the new stream belongs to the new tcp connection(10.0.2.2:60483-10.0.2.5:4444), not the original tcp connection(10.0.2.2:60482-10.0.2.5:4444)?

[yuweizzz]

It is hard to fix this problem, the better solution is use pcap mode. see #745 .

Thank you for your time! I read your comment in #745 and was a little confused. In your second example, you said that the new stream belongs to a different event worker than the first stream on the same tcp connection, and the different event workers cannot share the hpack decoder.

But in second example it seems that the new stream belongs to the new tcp connection(10.0.2.2:60483-10.0.2.5:4444), not the original tcp connection(10.0.2.2:60482-10.0.2.5:4444)?

the main tcp conn is 10.0.2.2:60482-10.0.2.5:4444, the error log also raise by it.

2025/02/28 12:00:24 [http2 response] Dump HTTP2 Frame error: connection error: COMPRESSION_ERROR
2025-02-28T12:00:24+08:00 ??? UUID:155734_155734_nginx_4_1_10.0.2.2:60482-10.0.2.5:4444, Name:HTTP2Response, Type:4, Length:855

10.0.2.2:60483-10.0.2.5:4444 is a new conn, it seem a browser behavior, and just sended WINDOW_UPDATE and SETTINGS.

another pcap example:

[huaixia777]

Okay, I see what you mean, that is, if a stream in the same tcp connection uses a new event worker, the hpack decoder cannot be shared, resulting in COMPRESSION_ERROR. Is this the problem?

[yuweizzz]

yes, because the deep reason is hpack dynamic table cannot be shared, see https://datatracker.ietf.org/doc/html/rfc7541#section-2.2

[cfc4n]

I’m trying new solutions, like having them use different event workers. @yuweizzz What do you think of this idea?

[yuweizzz]

the hpack decoder and 4-tuple will be the key part. If we can store the hpack decoder according to 4-tuple and find the correct one for each headers frame, it could be possible.

[cfc4n]

the hpack decoder and 4-tuple will be the key part. If we can store the hpack decoder according to 4-tuple and find the correct one for each headers frame, it could be possible.

最合适的解决方案，是SSLDataEvent 跟 connDataEvent 的数据，可以准确关联。 当前是使用PID、FD两个字段来关联，但是如果FD被关闭后，迅速内核复用，那么用户空间延迟删除的逻辑，会造成数据冲突，也就是说事件解码器被混用。

1. 尝试使用pid_fd_sockAddr来关联，但是，在SSLDataEvent里（即eBPF的uprobeSSL_write）中是获取不到sockAddr的。
2. 尝试让tcp_fd_infos以key struct key {pid_fd}、以struct value {sock_fd}为value，作为交换的DB，当 SSL_write触发时，再到这里读取sock的值，写入到SSLDataEvent中，用于用户空间的读取。发现还是失败，因为kprobe/inet_stream_connect的参数中，并没有fd信息。

经过今天的尝试，解决方案失败，我没有更好地思路了。

@Asphaltt 专家，你有更好的想法吗？