CRC errors on decompress

Bug #1533247 reported by Vadim Melikhov on 2016-01-12
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
rohc
Status tracked in Rohc-main
Rohc-2.0.x
Undecided
Didier Barvaux
Rohc-main
Undecided
Didier Barvaux

Bug Description

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

Changed in rohc:
assignee: nobody → Didier Barvaux (didier-barvaux)
tags: added: icmp library
Didier Barvaux (didier-barvaux) wrote :

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) wrote :
Download full text (4.4 KiB)

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...

Read more...

Changed in rohc:
milestone: none → 2.0.0
Didier Barvaux (didier-barvaux) wrote :

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.

tags: added: feedback
Vadim Melikhov (uprsnab) wrote :

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

Changed in rohc:
milestone: 2.0.0 → 2.1.0
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers