gnrc/ipv6: "invalid payload length" - corrupted IPv6 header when ENABLE_DEBUG=1 in mbox.c #20390
Open
Description
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