Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

gnrc/ipv6: "invalid payload length" - corrupted IPv6 header when ENABLE_DEBUG=1 in mbox.c #20390

Open
fabian18 opened this issue Feb 15, 2024 · 0 comments
Assignees
Labels
Area: network Area: Networking Area: tests Area: tests and testing framework Type: bug The issue reports a bug / The PR fixes a bug (including spelling errors)

Comments

@fabian18
Copy link
Contributor

fabian18 commented Feb 15, 2024

Description

I was actually trying to reproduce a packet leak (hence the unrelated branch name), but I found another race condition when ENABLE_DEBUG 1 in core/mbox.c. and data is sent at a certain speed when using gnrc UDP sockets.
I wrote a test application to receive UDP datagrams and a python script that sends UDP datagrams.
For reproduction you can find the branch here.
The IPv6 header corruption happens when you send data fast, for example every 100ms.
It does not happen when you send only every 1s.
The datagram size seems unrelated (tested with 1024 and 512).

Steps to reproduce the issue

Terminal1:
Create a SLIP interface on Linux.
cd dist/tools/tunslip
sudo ./tunslip6 -v4 -B 115200 -s /dev/ttyUSB0 fd00:fa:b1:18::1

Terminal 2:
I use same54-xpro with a TTL adapter to create a SLIP interface on UART_DEV(1).
cd tests/net/gnrc_sock_udp_pktbuf
BOARD=same54-xpro make flash term

Terminal 3:
Start the UDP sender
cd tests/net/gnrc_sock_udp_pktbuf/tests
python3 udp_sender.py <ip address of interface on board> 12345

Expected results

RIOT should receive all datagrams without issues.

Actual results

Every second received IPv6 header is corrupted and actually contains the data that was sent.
Consecuquently the packet is dropped because of an invalid length.

2024-02-15 13:21:37,042 # Received message 340
2024-02-15 13:21:37,045 # mbox: Thread 6 _wait(): going blocked.
2024-02-15 13:21:37,090 # ALLOCATE: 0x20003ad0, 24, 5
2024-02-15 13:21:37,092 # ALLOCATE: 0x20003ae8, 528, 5
2024-02-15 13:21:37,095 # ALLOCATE: 0x20003cf8, 24, 5
2024-02-15 13:21:37,097 # ALLOCATE: 0x20003d10, 8, 5
2024-02-15 13:21:37,099 # ALLOCATE: 0x20003d18, 24, 2
2024-02-15 13:21:37,105 # ipv6: invalid payload length: 520, actual: 483, dropping packet
2024-02-15 13:21:37,107 # FREE: 0x20003b10, 488, 2
2024-02-15 13:21:37,109 # FREE: 0x20003ad0, 24, 2
2024-02-15 13:21:37,111 # FREE: 0x20003ae8, 40, 2
2024-02-15 13:21:37,114 # FREE: 0x20003d18, 24, 2
2024-02-15 13:21:37,116 # FREE: 0x20003d10, 8, 2
2024-02-15 13:21:37,118 # FREE: 0x20003cf8, 24, 2
2024-02-15 13:21:37,190 # ALLOCATE: 0x20003ad0, 24, 5
2024-02-15 13:21:37,192 # ALLOCATE: 0x20003ae8, 560, 5
2024-02-15 13:21:37,195 # ALLOCATE: 0x20003d18, 24, 5
2024-02-15 13:21:37,197 # ALLOCATE: 0x20003d30, 8, 5
2024-02-15 13:21:37,200 # ALLOCATE: 0x20003d38, 24, 2
2024-02-15 13:21:37,209 # ipv6: Received (src = fe80::f8:b1:18:1, dst = fe80::e4b6:3248:b7d6:c67b, next header = 17, length = 520)
2024-02-15 13:21:37,211 # ALLOCATE: 0x20003d50, 24, 3
2024-02-15 13:21:37,217 # mbox: Thread 3 mbox 0x20000d44: _tryput(): there's a waiter.
2024-02-15 13:21:37,221 # mbox: Thread 3: _wake_waiter(): waking up 6.
2024-02-15 13:21:37,224 # mbox: Thread 6 _wait(): woke up.
2024-02-15 13:21:37,226 # FREE: 0x20003b18, 512, 6
2024-02-15 13:21:37,228 # FREE: 0x20003ad0, 24, 6
2024-02-15 13:21:37,230 # FREE: 0x20003b10, 8, 6
2024-02-15 13:21:37,232 # FREE: 0x20003d50, 24, 6
2024-02-15 13:21:37,234 # FREE: 0x20003ae8, 40, 6
2024-02-15 13:21:37,236 # FREE: 0x20003d38, 24, 6
2024-02-15 13:21:37,238 # FREE: 0x20003d30, 8, 6
2024-02-15 13:21:37,241 # FREE: 0x20003d18, 24, 6
2024-02-15 13:21:37,242 # Received message 342
2024-02-15 13:21:37,246 # mbox: Thread 6 _wait(): going blocked.
2024-02-15 13:21:37,290 # ALLOCATE: 0x20003ad0, 24, 5
2024-02-15 13:21:37,293 # ALLOCATE: 0x20003ae8, 528, 5
2024-02-15 13:21:37,295 # ALLOCATE: 0x20003cf8, 24, 5
2024-02-15 13:21:37,297 # ALLOCATE: 0x20003d10, 8, 5
2024-02-15 13:21:37,300 # ALLOCATE: 0x20003d18, 24, 2
2024-02-15 13:21:37,306 # ipv6: invalid payload length: 520, actual: 483, dropping packet
2024-02-15 13:21:37,308 # FREE: 0x20003b10, 488, 2
2024-02-15 13:21:37,310 # FREE: 0x20003ad0, 24, 2
2024-02-15 13:21:37,312 # FREE: 0x20003ae8, 40, 2
2024-02-15 13:21:37,314 # FREE: 0x20003d18, 24, 2
2024-02-15 13:21:37,316 # FREE: 0x20003d10, 8, 2
2024-02-15 13:21:37,318 # FREE: 0x20003cf8, 24, 2
2024-02-15 13:21:37,391 # ALLOCATE: 0x20003ad0, 24, 5
2024-02-15 13:21:37,393 # ALLOCATE: 0x20003ae8, 560, 5
2024-02-15 13:21:37,396 # ALLOCATE: 0x20003d18, 24, 5
2024-02-15 13:21:37,398 # ALLOCATE: 0x20003d30, 8, 5
2024-02-15 13:21:37,400 # ALLOCATE: 0x20003d38, 24, 2
2024-02-15 13:21:37,410 # ipv6: Received (src = fe80::f8:b1:18:1, dst = fe80::e4b6:3248:b7d6:c67b, next header = 17, length = 520)
2024-02-15 13:21:37,412 # ALLOCATE: 0x20003d50, 24, 3
2024-02-15 13:21:37,418 # mbox: Thread 3 mbox 0x20000d44: _tryput(): there's a waiter.
2024-02-15 13:21:37,422 # mbox: Thread 3: _wake_waiter(): waking up 6.
2024-02-15 13:21:37,424 # mbox: Thread 6 _wait(): woke up.
2024-02-15 13:21:37,427 # FREE: 0x20003b18, 512, 6
2024-02-15 13:21:37,429 # FREE: 0x20003ad0, 24, 6
2024-02-15 13:21:37,431 # FREE: 0x20003b10, 8, 6
2024-02-15 13:21:37,433 # FREE: 0x20003d50, 24, 6
2024-02-15 13:21:37,435 # FREE: 0x20003ae8, 40, 6
2024-02-15 13:21:37,437 # FREE: 0x20003d38, 24, 6
2024-02-15 13:21:37,439 # FREE: 0x20003d30, 8, 6
2024-02-15 13:21:37,441 # FREE: 0x20003d18, 24, 6
2024-02-15 13:21:37,443 # Received message 344
2024-02-15 13:21:37,448 # Packets: 173, Data: 88576 Bytes, Speed: 2552 Bytes/s
2024-02-15 13:21:37,451 # mbox: Thread 6 _wait(): going blocked.
2024-02-15 13:21:37,491 # ALLOCATE: 0x20003ad0, 24, 5
2024-02-15 13:21:37,493 # ALLOCATE: 0x20003ae8, 528, 5
2024-02-15 13:21:37,496 # ALLOCATE: 0x20003cf8, 24, 5
2024-02-15 13:21:37,498 # ALLOCATE: 0x20003d10, 8, 5
2024-02-15 13:21:37,501 # ALLOCATE: 0x20003d18, 24, 2
2024-02-15 13:21:37,506 # ipv6: invalid payload length: 520, actual: 483, dropping packet
2024-02-15 13:21:37,508 # FREE: 0x20003b10, 488, 2
2024-02-15 13:21:37,511 # FREE: 0x20003ad0, 24, 2
2024-02-15 13:21:37,513 # FREE: 0x20003ae8, 40, 2
2024-02-15 13:21:37,515 # FREE: 0x20003d18, 24, 2
2024-02-15 13:21:37,517 # FREE: 0x20003d10, 8, 2
2024-02-15 13:21:37,519 # FREE: 0x20003cf8, 24, 2
2024-02-15 13:21:37,591 # ALLOCATE: 0x20003ad0, 24, 5
2024-02-15 13:21:37,594 # ALLOCATE: 0x20003ae8, 560, 5
2024-02-15 13:21:37,596 # ALLOCATE: 0x20003d18, 24, 5
2024-02-15 13:21:37,598 # ALLOCATE: 0x20003d30, 8, 5
2024-02-15 13:21:37,601 # ALLOCATE: 0x20003d38, 24, 2
2024-02-15 13:21:37,610 # ipv6: Received (src = fe80::f8:b1:18:1, dst = fe80::e4b6:3248:b7d6:c67b, next header = 17, length = 520)
2024-02-15 13:21:37,613 # ALLOCATE: 0x20003d50, 24, 3
2024-02-15 13:21:37,618 # mbox: Thread 3 mbox 0x20000d44: _tryput(): there's a waiter.
2024-02-15 13:21:37,622 # mbox: Thread 3: _wake_waiter(): waking up 6.
2024-02-15 13:21:37,625 # mbox: Thread 6 _wait(): woke up.
2024-02-15 13:21:37,627 # FREE: 0x20003b18, 512, 6
2024-02-15 13:21:37,629 # FREE: 0x20003ad0, 24, 6
2024-02-15 13:21:37,631 # FREE: 0x20003b10, 8, 6
2024-02-15 13:21:37,633 # FREE: 0x20003d50, 24, 6
2024-02-15 13:21:37,635 # FREE: 0x20003ae8, 40, 6
2024-02-15 13:21:37,638 # FREE: 0x20003d38, 24, 6
2024-02-15 13:21:37,639 # FREE: 0x20003d30, 8, 6
2024-02-15 13:21:37,642 # FREE: 0x20003d18, 24, 6
2024-02-15 13:21:37,643 # Received message 346
2024-02-15 13:21:37,647 # mbox: Thread 6 _wait(): going blocked.
2024-02-15 13:21:37,691 # ALLOCATE: 0x20003ad0, 24, 5
2024-02-15 13:21:37,694 # ALLOCATE: 0x20003ae8, 528, 5
2024-02-15 13:21:37,696 # ALLOCATE: 0x20003cf8, 24, 5
2024-02-15 13:21:37,699 # ALLOCATE: 0x20003d10, 8, 5
2024-02-15 13:21:37,701 # ALLOCATE: 0x20003d18, 24, 2
2024-02-15 13:21:37,707 # ipv6: invalid payload length: 520, actual: 483, dropping packet
2024-02-15 13:21:37,709 # FREE: 0x20003b10, 488, 2
2024-02-15 13:21:37,711 # FREE: 0x20003ad0, 24, 2
2024-02-15 13:21:37,713 # FREE: 0x20003ae8, 40, 2
2024-02-15 13:21:37,715 # FREE: 0x20003d18, 24, 2
2024-02-15 13:21:37,717 # FREE: 0x20003d10, 8, 2
2024-02-15 13:21:37,719 # FREE: 0x20003cf8, 24, 2
2024-02-15 13:21:37,792 # ALLOCATE: 0x20003ad0, 24, 5
2024-02-15 13:21:37,794 # ALLOCATE: 0x20003ae8, 560, 5
2024-02-15 13:21:37,797 # ALLOCATE: 0x20003d18, 24, 5
2024-02-15 13:21:37,799 # ALLOCATE: 0x20003d30, 8, 5
2024-02-15 13:21:37,802 # ALLOCATE: 0x20003d38, 24, 2
2024-02-15 13:21:37,811 # ipv6: Received (src = fe80::f8:b1:18:1, dst = fe80::e4b6:3248:b7d6:c67b, next header = 17, length = 520)
2024-02-15 13:21:37,814 # ALLOCATE: 0x20003d50, 24, 3
2024-02-15 13:21:37,819 # mbox: Thread 3 mbox 0x20000d44: _tryput(): there's a waiter.
2024-02-15 13:21:37,823 # mbox: Thread 3: _wake_waiter(): waking up 6.
2024-02-15 13:21:37,826 # mbox: Thread 6 _wait(): woke up.
2024-02-15 13:21:37,828 # FREE: 0x20003b18, 512, 6
2024-02-15 13:21:37,830 # FREE: 0x20003ad0, 24, 6
2024-02-15 13:21:37,832 # FREE: 0x20003b10, 8, 6
2024-02-15 13:21:37,834 # FREE: 0x20003d50, 24, 6
2024-02-15 13:21:37,836 # FREE: 0x20003ae8, 40, 6
2024-02-15 13:21:37,838 # FREE: 0x20003d38, 24, 6
2024-02-15 13:21:37,840 # FREE: 0x20003d30, 8, 6
2024-02-15 13:21:37,843 # FREE: 0x20003d18, 24, 6
2024-02-15 13:21:37,844 # Received message 348
2024-02-15 13:21:37,848 # mbox: Thread 6 _wait(): going blocked.

Versions

Last RIOT master commit: 270aa7012fab0ceadeb0b82546ea06dbfe9c0902

@fabian18 fabian18 added Type: bug The issue reports a bug / The PR fixes a bug (including spelling errors) Area: network Area: Networking Area: tests Area: tests and testing framework labels Feb 15, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area: network Area: Networking Area: tests Area: tests and testing framework Type: bug The issue reports a bug / The PR fixes a bug (including spelling errors)
Projects
None yet
Development

No branches or pull requests

2 participants