CRC errors on decompress

[Vadim Melikhov]

Sometimes (~1-2 per 10k packets) I got ROHC_STATUS_BAD_CRC or ROHC_STATUS_MALFORMED errors while call function rohc_decompress3, At first I check CRCs from output of compressor and from INPUT of compressor. CRCs same.
Traffic - just ICMP stream from ping

COMPRESSOR OUTPUT
ROHC_COMP crc=0x3DFCA3C1
[ 0000] 82 00 D7 08 00 8B C0 4B 40 18 94 18 29 95 56 00 .......K ......V.
[ 0016] 00 00 00 9B 18 01 00 00 00 00 00 10 11 12 13 14 ........ ........
[ 0032] 15 16 17 18 19 1A 1B 1C 1D 1E 1F 20 21 22 23 24 ........ ........
[ 0048] 25 26 27 28 29 2A 2B 2C 2D 2E 2F 30 31 32 33 34 ........ ...01234
[ 0064] 35 36 37

DECOMPRESSOR INPUT
[ 0.000] COM Can't decompress ROHC packet. status=2 CRC=0x3DFCA3C1
[ 0000] 82 00 D7 08 00 8B C0 4B 40 18 94 18 29 95 56 00 .......K ......V.
[ 0016] 00 00 00 9B 18 01 00 00 00 00 00 10 11 12 13 14 ........ ........
[ 0032] 15 16 17 18 19 1A 1B 1C 1D 1E 1F 20 21 22 23 24 ........ ........
[ 0048] 25 26 27 28 29 2A 2B 2C 2D 2E 2F 30 31 32 33 34 ........ ...01234
[ 0064] 35 36 37

[rohc_decomp.c:780 rohc_decompress3()] decompress the 66-byte packet #2133
[rohc_decomp.c:3645 rohc_decomp_parse_padding()] skip 0 byte(s) of padding
[rohc_decomp.c:1024 d_decode_header()] decompressor received 0 bytes of feedback for the same-side associated compressor
[rohc_decomp.c:3608 rohc_decomp_decode_cid()] 1-byte large CID = 0
[rohc_decomp.c:3762 rohc_decomp_find_context()] context with CID 0 found
[rohc_decomp.c:1180 d_decode_header()] 6 bits required for SN in feedback (6 bits required for RTT, 16 max)
[rohc_decomp.c:1199 d_decode_header()] decode packet as 'UO-0'
[rohc_decomp.c:1370 rohc_decomp_decode_pkt()] parse packet type 'UO-0' (2)
[rohc_decomp_rfc3095.c:1467 parse_uo0()] 4 SN bits = 0xe
[rohc_decomp_rfc3095.c:1472 parse_uo0()] CRC-3 found in packet = 0x03
[rohc_decomp.c:1388 rohc_decomp_decode_pkt()] ROHC payload (length = 64 bytes) starts at offset 2
[rohc_decomp_rfc3095.c:5630 rfc3095_decomp_decode_bits()] decoded SN = 44942 / 0xaf8e (nr bits = 4, bits = 14 / 0xe)
[rohc_decomp_rfc3095.c:5722 decode_ip_values_from_bits()] decoded outer TOS/TC = 0
[rohc_decomp_rfc3095.c:5735 decode_ip_values_from_bits()] decoded outer TTL/HL = 64
[rohc_decomp_rfc3095.c:5749 decode_ip_values_from_bits()] decoded outer protocol/NH = 1
[rohc_decomp_rfc3095.c:5765 decode_ip_values_from_bits()] decoded outer NBO = 1
[rohc_decomp_rfc3095.c:5778 decode_ip_values_from_bits()] decoded outer RND = 0
[rohc_decomp_rfc3095.c:5791 decode_ip_values_from_bits()] decoded outer SID = 0
[rohc_decomp_rfc3095.c:5850 decode_ip_values_from_bits()] decoded outer IP-ID = 0xef5c (rnd = 0, nbo = 1, sid = 0, nr bits = 0, bits = 0x0)
[rohc_decomp_rfc3095.c:5863 decode_ip_values_from_bits()] decoded outer DF = 1
[rohc_decomp_rfc3095.c:5879 decode_ip_values_from_bits()] decoded outer src address = 03030303 (3.3.3.3)
[rohc_decomp_rfc3095.c:5895 decode_ip_values_from_bits()] decoded outer dst address = 04040404 (4.4.4.4)
[rohc_decomp_rfc3095.c:5046 rfc3095_decomp_build_hdrs()] length of transport header = 0 bytes
[rohc_decomp_rfc3095.c:5208 build_uncomp_ipv4()] Total Length = 0x0054 (IHL * 4 + 64)
[rohc_decomp_rfc3095.c:5212 build_uncomp_ipv4()] IP checksum = 0x3d3f
[rohc_decomp_rfc3095.c:5366 check_uncomp_crc()] CRC-3 on uncompressed header = 0x2
[rohc_decomp_rfc3095.c:5372 check_uncomp_crc()] CRC failure (computed = 0x02, packet = 0x03)
[rohc_decomp_rfc3095.c:5100 rfc3095_decomp_build_hdrs()] CRC detected a decompression failure for packet of type UO-0 in state Full Context and mode U-mode
[rohc_decomp.c:1509 rohc_decomp_decode_pkt()] CID 0: failed to build uncompressed headers (CRC failure)
[rohc_decomp_rfc3095.c:5412 rfc3095_decomp_attempt_repair()] CID 0: CRC repair: feature disabled
[rohc_decomp.c:1522 rohc_decomp_decode_pkt()] CID 0: failed to build uncompressed headers (CRC failure)
[rohc_decomp.c:1251 d_decode_header()] failed to decompress packet (code = 4)
[rohc_decomp.c:802 rohc_decompress3()] stay in U-mode as requested by user
[rohc_decomp.c:889 rohc_decompress3()] packet decompression failed: CRC failure (4)
[rohc_decomp.c:2033 rohc_decomp_feedback_nack()] CID 0: U-mode: Full Context state: UO-0 packet failed the CRC check
[rohc_decomp.c:2152 rohc_decomp_feedback_nack()] avoid sending feedback too quickly (100 of 3200 with threshold 960)
[rohc_decomp.c:2206 rohc_decomp_feedback_nack()] do not send a negative ACK
[rohc_decomp.c:2298 rohc_decomp_feedback_nack()] do not perform a downward state transition

then I enabled ROHC_DECOMP_FEATURE_CRC_REPAIR I got next LOG

[rohc_decomp.c:780 rohc_decompress3()] decompress the 67-byte packet #11442
[rohc_decomp.c:3645 rohc_decomp_parse_padding()] skip 0 byte(s) of padding
[rohc_decomp.c:1024 d_decode_header()] decompressor received 0 bytes of feedback for the same-side associated compressor
[rohc_decomp.c:3608 rohc_decomp_decode_cid()] 1-byte large CID = 0
[rohc_decomp.c:3762 rohc_decomp_find_context()] context with CID 0 found
[rohc_decomp.c:1180 d_decode_header()] 6 bits required for SN in feedback (6 bits required for RTT, 16 max)
[rohc_decomp.c:1199 d_decode_header()] decode packet as 'UO-1'
[rohc_decomp.c:1370 rohc_decomp_decode_pkt()] parse packet type 'UO-1' (3)
[rohc_decomp_rfc3095.c:1676 parse_uo1()] 6 IP-ID bits for IP header #1 = 0x8
[rohc_decomp_rfc3095.c:1700 parse_uo1()] 5 SN bits = 0x2
[rohc_decomp_rfc3095.c:1705 parse_uo1()] CRC-3 found in packet = 0x06
[rohc_decomp.c:1388 rohc_decomp_decode_pkt()] ROHC payload (length = 64 bytes) starts at offset 3
[rohc_decomp_rfc3095.c:5630 rfc3095_decomp_decode_bits()] decoded SN = 57890 / 0xe222 (nr bits = 5, bits = 2 / 0x2)
[rohc_decomp_rfc3095.c:5722 decode_ip_values_from_bits()] decoded outer TOS/TC = 0
[rohc_decomp_rfc3095.c:5735 decode_ip_values_from_bits()] decoded outer TTL/HL = 64
[rohc_decomp_rfc3095.c:5749 decode_ip_values_from_bits()] decoded outer protocol/NH = 1
[rohc_decomp_rfc3095.c:5765 decode_ip_values_from_bits()] decoded outer NBO = 1
[rohc_decomp_rfc3095.c:5778 decode_ip_values_from_bits()] decoded outer RND = 0
[rohc_decomp_rfc3095.c:5791 decode_ip_values_from_bits()] decoded outer SID = 0
[rohc_decomp_rfc3095.c:5850 decode_ip_values_from_bits()] decoded outer IP-ID = 0xb02a (rnd = 0, nbo = 1, sid = 0, nr bits = 6, bits = 0x8)
[rohc_decomp_rfc3095.c:5863 decode_ip_values_from_bits()] decoded outer DF = 1
[rohc_decomp_rfc3095.c:5879 decode_ip_values_from_bits()] decoded outer src address = 03030303 (3.3.3.3)
[rohc_decomp_rfc3095.c:5895 decode_ip_values_from_bits()] decoded outer dst address = 04040404 (4.4.4.4)
[rohc_decomp_rfc3095.c:5046 rfc3095_decomp_build_hdrs()] length of transport header = 0 bytes
[rohc_decomp_rfc3095.c:5208 build_uncomp_ipv4()] Total Length = 0x0054 (IHL * 4 + 64)
[rohc_decomp_rfc3095.c:5212 build_uncomp_ipv4()] IP checksum = 0x7c71
[rohc_decomp_rfc3095.c:5366 check_uncomp_crc()] CRC-3 on uncompressed header = 0x6
[rohc_decomp.c:1477 rohc_decomp_decode_pkt()] CID 0: CRC repair: CRC is correct
[rohc_decomp.c:1548 rohc_decomp_decode_pkt()] CID 0: CRC repair: throw away packet, still 1 CRC-valid packets required
[rohc_decomp.c:1251 d_decode_header()] failed to decompress packet (code = 4)
[rohc_decomp.c:802 rohc_decompress3()] stay in U-mode as requested by user
[rohc_decomp.c:889 rohc_decompress3()] packet decompression failed: CRC failure (4)
[rohc_decomp.c:2033 rohc_decomp_feedback_nack()] CID 0: U-mode: Full Context state: UO-1 packet failed the CRC check
[rohc_decomp.c:2152 rohc_decomp_feedback_nack()] avoid sending feedback too quickly (300 of 3200 with threshold 960)
[rohc_decomp.c:2206 rohc_decomp_feedback_nack()] do not send a negative ACK
[rohc_decomp.c:2298 rohc_decomp_feedback_nack()] do not perform a downward state transition
[ 0.000] COM F:rohc_decomp: Can't decompress ROHC packet. status=4 ('CRC failure') CRC=0xC4F88808
[ 0000] 88 00 16 08 00 78 70 4B 60 1E F8 8D 2F 95 56 00 .....xpK ......V.
[ 0016] 00 00 00 2F DE 04 00 00 00 00 00 10 11 12 13 14 ........ ........
[ 0032] 15 16 17 18 19 1A 1B 1C 1D 1E 1F 20 21 22 23 24 ........ ........
[ 0048] 25 26 27 28 29 2A 2B 2C 2D 2E 2F 30 31 32 33 34 ........ ...01234
[ 0064] 35 36 37 567

[Didier Barvaux (didier-barvaux)]

Hello,

Thank you for the bug report. I got a few questions for you.

* What version of the ROHC library are you using?
* What is your configuration (looks like large CID, what W-LSB window width...)?
* Are there only ICMP packets?
* Is there one single ICMP stream or several in parallel?
* Is there some packet loss or reordering between the ROHC compressor and the ROHC decompressor?
* The first ROHC traces seem not to match the first packet dump, should they?
* Is it possible to capture (with tcpdump or wireshark) the uncompressed (and maybe the compressed too) stream of packets until a CRC error occurs? Please use option -s0 if using tcpdump. Attach the files to the bug report. If the file are too large for Launchpad, try to compress them, or upload them somewhere else.

Regards,
Didier

[Vadim Melikhov (uprsnab)]

Hello, thank you for great work.

I use last version (git master) librohc 2.0
- I try with diffrent configurations small cid and large cid, W-LSB side is standard (4) try set 8 with same result, try ROHC_U_MODE and ROHC_O_MODE
- Profiles enabled: ROHC_PROFILE_IP ROHC_PROFILE_UDP ROHC_PROFILE_RTP
- Only ICMP packets
- This happends only then run multiple ping's (I try with 20 several paralles ping's to same host ). This single ping all works fine even if I enable flood mode.
- Loss & delay emulated with netem. Loss: 0.5% Delay: 30ms. As I see if channel are lossless I observer no problems like this.

Today I got another kind of error.
20 parallels ICMP ping's
Loss: 0.5% Delay: 30ms
ROHC_LARGE_CID, ROHC_LARGE_CID_MAX, bits: 8 O_MODE
one side just stop decompress everything and send no feedback's at all

---- PROBLEM SIDE ---
On feedback recieved from remote side ----------
[rohc_decomp.c:780 rohc_decompress3()] decompress the 3-byte packet #84598
[rohc_decomp.c:3645 rohc_decomp_parse_padding()] skip 0 byte(s) of padding
[rohc_decomp.c:3859 rohc_decomp_parse_feedbacks()] parse feedback item #1 at offset 0 in ROHC packet
[rohc_decomp.c:3921 rohc_decomp_parse_feedback()] feedback found (header = 1 bytes, data = 2 bytes)
[rohc_decomp.c:1024 d_decode_header()] decompressor received 3 bytes of feedback for the same-side associated compressor
[rohc_decomp.c:1033 d_decode_header()] feedback-only packet, stop decompression
[rohc_decomp.c:855 rohc_decompress3()] packet decompression succeeded
[rohc_comp.c:1910 rohc_comp_deliver_feedback2()] deliver 3 byte(s) of feedback to the right context
[rohc_comp.c:1938 rohc_comp_deliver_feedback2()] feedback found (header = 1 bytes, data = 2 bytes)
[rohc_comp.c:1812 __rohc_comp_deliver_feedback()] deliver 2 byte(s) of feedback to the right context
[rohc_comp.c:2756 rohc_comp_feedback_parse_cid()] feedback CID = 0
[rohc_comp_rfc3095.c:924 rohc_comp_rfc3095_feedback()] FEEDBACK-1 received
[rohc_comp_rfc3095.c:932 rohc_comp_rfc3095_feedback()] ACK received (CID = 0, 8-bit SN = 0x68)
[rohc_comp_rfc3095.c:1132 rohc_comp_rfc3095_feedback_ack()] ACK(O) received, but not supported, so do not transit to SO state more quickly
[rohc_comp_rfc3095.c:1220 rohc_comp_rfc3095_feedback_ack()] ACK received, but not fully supported, so do not acknowledge compressed list more quickly
[rohc_comp.c:1866 __rohc_comp_deliver_feedback()] FEEDBACK-1 data successfully handled

On decompress ---------------------------------
[ 0.000] PRT F:tdx_deasm_raw: GOT TDX_PKT_T_RAW SEQ=89089 rohc=YES
[ 0.000] FLW F:tdx_flow_raw_serialized: RAW_SEQ=89089 LAST_SEQ=89088
[rohc_decomp.c:780 rohc_decompress3()] decompress the 67-byte packet #84599
[rohc_decomp.c:3645 rohc_decomp_parse_padding()] skip 0 byte(s) of padding
[rohc_decomp.c:1024 d_decode_header()] decompressor received 0 bytes of feedback for the same-side associated compressor
[rohc_decomp.c:3608 rohc_decomp_decode_cid()] 1-byte large CID = 0
[rohc_decomp.c:3762 rohc_decomp_find_context()] context with CID 0 found
[rohc_decomp.c:1180 d_decode_header()] 6 bits required for SN in feedback (6 bits required for RTT, 16 max)
[rohc_decomp.c:1199 d_decode_header()] decode packet as 'UO-1'
[ro...

[Didier Barvaux (didier-barvaux)]

Ok, I have configured some packet loss, so the decompression failure might be expected. The decompressor should send a negative feedback however. There is a threshold to reach before sending a NACK, then there is some rate-limiting once the threshold is reached. Maybe this is the root of your problem. Or maybe there is a bug in those mechanisms. The PCAP and logs will help a lot. Please also specify the Git sha1 that you are testing.

[Vadim Melikhov (uprsnab)]

SHA1: 787799fb6442c2dc2f2e72f05a8afff095e2ff73
About rate limiting - I observe 5-6 minutes and decompressor send no feedback until this time.