kernel timeout_list NULL pointer access

[chyu313]

I use MIMXRT1060_EVK board to run Zephyr. To avoid NULL pointer access, I use MPU to set ARM address 0x0 (located in ITCM which is not used in my program) as no-access attribute, so that NULL pointer access to 0 will cause MPU FAULT. A NULL pointer access occurs in remove_timeout() which is called by sys_clock_announce() in kernel/timeout.c.

E: ***** MPU FAULT *****
E:   Data Access Violation
E:   MMFAR Address: 0x4
E: r0/a1:  0x80198f18  r1/a2:  0x00017db0  r2/a3:  0x80002f60
E: r3/a4:  0x00000000 r12/ip:  0x00000000 r14/lr:  0x6000dfc9
E:  xpsr:  0x2100020f
E: r4/v1:  0x00000000  r5/v2:  0x80006d80  r6/v3:  0x80094064
E: r7/v4:  0x00000000  r8/v5:  0x80002f60  r9/v6:  0x00000000
E: r10/v7: 0x60004bf1  r11/v8: 0x800ec57c    psp:  0x800ec4b0
E: EXC_RETURN: 0xfffffff1
E: Faulting instruction address (r15/pc): 0x6000ddee
E: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
E: Fault during interrupt handling

E: Current thread: 0x800046b8 (tcpc_11)
E: Halting system

"Faulting instruction address (r15/pc): 0x6000ddee" is executing next->prev = prev; in sys_dlist_remove().
next pointer represented by r3 should not be NULL (0).

	next->prev = prev;
6000ddee:	605a      	str	r2, [r3, #4]

The following is the complete assembly code of remove_timeout() in which sys_dlist_remove() is called.

6000ddc8 <remove_timeout>:
	return (node == list->tail) ? NULL : node->next;
6000ddc8:	6803      	ldr	r3, [r0, #0]
{
6000ddca:	b530      	push	{r4, r5, lr}
	return (node != NULL) ? sys_dlist_peek_next_no_check(list, node) : NULL;
6000ddcc:	b168      	cbz	r0, 6000ddea <remove_timeout+0x22>
	return (node == list->tail) ? NULL : node->next;
6000ddce:	4a0a      	ldr	r2, [pc, #40]	; (6000ddf8 <remove_timeout+0x30>)
6000ddd0:	6852      	ldr	r2, [r2, #4]
6000ddd2:	4290      	cmp	r0, r2
6000ddd4:	d009      	beq.n	6000ddea <remove_timeout+0x22>
	if (next(t) != NULL) {
6000ddd6:	b143      	cbz	r3, 6000ddea <remove_timeout+0x22>
		next(t)->dticks += t->dticks;
6000ddd8:	e9d3 2104 	ldrd	r2, r1, [r3, #16]
6000dddc:	e9d0 4504 	ldrd	r4, r5, [r0, #16]
6000dde0:	1912      	adds	r2, r2, r4
6000dde2:	eb41 0105 	adc.w	r1, r1, r5
6000dde6:	e9c3 2104 	strd	r2, r1, [r3, #16]
 * @return N/A
 */

static inline void sys_dlist_remove(sys_dnode_t *node)
{
	sys_dnode_t *const prev = node->prev;
6000ddea:	6842      	ldr	r2, [r0, #4]
	sys_dnode_t *const next = node->next;

	prev->next = next;
6000ddec:	6013      	str	r3, [r2, #0]
	next->prev = prev;
6000ddee:	605a      	str	r2, [r3, #4]
	node->next = NULL;
6000ddf0:	2300      	movs	r3, #0
	node->prev = NULL;
6000ddf2:	e9c0 3300 	strd	r3, r3, [r0]
}
6000ddf6:	bd30      	pop	{r4, r5, pc}
6000ddf8:	80002f60 	.word	0x80002f60

6000ddfc <timeout_rem>:
	return ret;
}

To Reproduce
The following is main.c used to duplicate the phenomenon. 32 TCP server threads and 32 TCP client threads are created. TCP client thread tries to connect to local server. Zephyr does not support IP loopback interface, so TCP client connection fails and then continues to try connection. After few minutes, MPU fault occurs.

#include <zephyr.h>
#include <stdio.h>
#include <net/socket.h>

#define NUM_THREAD  32
#define THREAD_STACK_SIZE 8192
#define THREAD_PRIORITY K_PRIO_COOP(8)
K_THREAD_STACK_ARRAY_DEFINE(tcpserver_stack, NUM_THREAD,
			    THREAD_STACK_SIZE);
struct k_thread tcpserver_thread[NUM_THREAD];
K_THREAD_STACK_ARRAY_DEFINE(tcpclient_stack, NUM_THREAD,
			    THREAD_STACK_SIZE);
struct k_thread tcpclient_thread[NUM_THREAD];

void tcpserver(void *ptr1, void *ptr2, void *ptr3)
{
    int tcpport = (int)ptr1;
    int listen_fd, data_fd;
    struct sockaddr_in sin;
    int n;

    listen_fd = zsock_socket(AF_INET, SOCK_STREAM, IPPROTO_TCP);
    if (listen_fd <= 0) {
        return;
    }
    sin.sin_family = AF_INET;
    sin.sin_port = htons(tcpport);
    sin.sin_addr.s_addr = INADDR_ANY;
    zsock_bind(listen_fd, (const struct sockaddr *)&sin, sizeof(sin));
    zsock_listen(listen_fd, 1);
    while (1) {
        n = sizeof(struct sockaddr_in);
        data_fd = zsock_accept(listen_fd, (struct sockaddr *)&sin, &n);
        zsock_close(data_fd);
    }
}

void tcpclient(void *ptr1, void *ptr2, void *ptr3)
{
    int tcpport = (int)ptr1;
    int fd;
    struct sockaddr_in sin;

    while (1) {
        fd = zsock_socket(AF_INET, SOCK_STREAM, IPPROTO_TCP);
        if (fd <= 0) {
            return;
        }
        sin.sin_family = AF_INET;
        sin.sin_port = htons(tcpport);
        sin.sin_addr.s_addr = 0x0100007F; /* 127.0.0.1 */
        zsock_connect(fd, (struct sockaddr *)&sin, sizeof(sin));
        zsock_close(fd);
    }
}

void main(void)
{
    int i;
    char name[64];

    for (i = 0; i < NUM_THREAD; i++) {
    	k_thread_create(&tcpserver_thread[i], tcpserver_stack[i],
    	    K_THREAD_STACK_SIZEOF(tcpserver_stack[i]), tcpserver,
    	    (void *)(4001 + i), NULL, NULL, THREAD_PRIORITY, 0, K_NO_WAIT);
        snprintf(name, sizeof(name), "tcps_%d", i);
    	k_thread_name_set(&tcpserver_thread[i], name);
    	k_thread_start(&tcpserver_thread[i]);

    	k_thread_create(&tcpclient_thread[i], tcpclient_stack[i],
    	    K_THREAD_STACK_SIZEOF(tcpclient_stack[i]), tcpclient,
    	    (void *)(4001 + i), NULL, NULL, THREAD_PRIORITY, 0, K_NO_WAIT);
        snprintf(name, sizeof(name), "tcpc_%d", i);
    	k_thread_name_set(&tcpclient_thread[i], name);
    	k_thread_start(&tcpclient_thread[i]);
    }
}

Impact
This is a test to cause potential problem. Multi-thread sockets program can cause system crash as in #32564

Environment

• OS: Linux
• Toolchain: Zephyr SDK
• Commit 75a2ef8

[jukkar]

Zephyr does not support IP loopback interface

Loopback is supported, just set CONFIG_NET_LOOPBACK to enable it.

[jukkar]

Can be replicated with native_posix

*** Booting Zephyr OS build zephyr-v2.6.0-315-gde2e14177b37  ***
==20141== Thread 4:
==20141== Invalid write of size 4
==20141==    at 0x80693F2: sys_dlist_remove (dlist.h:514)
==20141==    by 0x80693F2: remove_timeout (timeout.c:59)
==20141==    by 0x8069719: sys_clock_announce (timeout.c:250)
==20141==    by 0x805260D: vector_to_irq (irq_handler.c:49)
==20141==    by 0x805260D: posix_irq_handler (irq_handler.c:93)
==20141==    by 0x805260D: posix_irq_handler (irq_handler.c:66)
==20141==    by 0x8067BA9: k_cpu_idle (kernel.h:5419)
==20141==    by 0x8067BA9: idle (idle.c:98)
==20141==    by 0x804A0FB: z_thread_entry (thread_entry.c:29)
==20141==    by 0x8051771: posix_thread_starter (posix_core.c:305)
==20141==    by 0x414467F: start_thread (in /usr/lib/libpthread-2.31.so)
==20141==    by 0x4254829: clone (in /usr/lib/libc-2.31.so)
==20141==  Address 0x4 is not stack'd, malloc'd or (recently) free'd
==20141== 
==20141== 
==20141== Process terminating with default action of signal 11 (SIGSEGV): dumping core
==20141==  Access not within mapped region at address 0x4
==20141==    at 0x80693F2: sys_dlist_remove (dlist.h:514)
==20141==    by 0x80693F2: remove_timeout (timeout.c:59)
==20141==    by 0x8069719: sys_clock_announce (timeout.c:250)
==20141==    by 0x805260D: vector_to_irq (irq_handler.c:49)
==20141==    by 0x805260D: posix_irq_handler (irq_handler.c:93)
==20141==    by 0x805260D: posix_irq_handler (irq_handler.c:66)
==20141==    by 0x8067BA9: k_cpu_idle (kernel.h:5419)
==20141==    by 0x8067BA9: idle (idle.c:98)
==20141==    by 0x804A0FB: z_thread_entry (thread_entry.c:29)
==20141==    by 0x8051771: posix_thread_starter (posix_core.c:305)
==20141==    by 0x414467F: start_thread (in /usr/lib/libpthread-2.31.so)
==20141==    by 0x4254829: clone (in /usr/lib/libc-2.31.so)
==20141==  If you believe this happened as a result of a stack
==20141==  overflow in your program's main thread (unlikely but
==20141==  possible), you can try to increase the size of the
==20141==  main thread stack using the --main-stacksize= flag.
==20141==  The main thread stack size used in this run was 8388608.
==20141== 

[jukkar]

Note that because 0 is a valid fd, the check in tcpserver thread needs to look like this

    if (listen_fd < 0) {
        return;
    }

As almost every limit in Zephyr is determined at build time, some networking limits need to be increased because you are creating quite many sockets etc. in the application. So I compiled the application like this in order to increase the socket count etc.

cmake . -Bbuild -DBOARD=native_posix -DCONFIG_NATIVE_UART_AUTOATTACH_DEFAULT_CMD=\""gnome-terminal -- screen %s"\" -DCONFIG_NET_MAX_CONTEXTS=96  -DCONFIG_NET_PKT_RX_COUNT=96 -DCONFIG_NET_PKT_TX_COUNT=96 -DCONFIG_NET_MAX_CONN=96 -DCONFIG_NET_BUF_RX_COUNT=128 -DCONFIG_NET_BUF_TX_COUNT=128  -DCONFIG_NET_LOOPBACK=y -DCONFIG_NET_CONFIG_MY_IPV4_ADDR=\""127.0.0.1"\"

This helped a bit although I am still seeing error prints in console and eventually there is a crash like this.

*** Booting Zephyr OS build zephyr-v2.6.0-316-g8934cd6304da  ***
==49357== Thread 4:
==49357== Jump to the invalid address stated on the next line
==49357==    at 0x0: ???
==49357==    by 0x8052729: vector_to_irq (irq_handler.c:49)
==49357==    by 0x8052729: posix_irq_handler (irq_handler.c:93)
==49357==    by 0x8052729: posix_irq_handler (irq_handler.c:66)
==49357==    by 0x806647C: k_cpu_idle (kernel.h:5419)
==49357==    by 0x806647C: idle (idle.c:98)
==49357==    by 0x804A0DB: z_thread_entry (thread_entry.c:29)
==49357==    by 0x805188D: posix_thread_starter (posix_core.c:305)
==49357==    by 0x414467F: start_thread (in /usr/lib/libpthread-2.31.so)
==49357==    by 0x4254829: clone (in /usr/lib/libc-2.31.so)
==49357==  Address 0x0 is not stack'd, malloc'd or (recently) free'd
==49357== 
==49357== 
==49357== Process terminating with default action of signal 11 (SIGSEGV): dumping core
==49357==  Bad permissions for mapped region at address 0x0
==49357==    at 0x0: ???
==49357==    by 0x8052729: vector_to_irq (irq_handler.c:49)
==49357==    by 0x8052729: posix_irq_handler (irq_handler.c:93)
==49357==    by 0x8052729: posix_irq_handler (irq_handler.c:66)
==49357==    by 0x806647C: k_cpu_idle (kernel.h:5419)
==49357==    by 0x806647C: idle (idle.c:98)
==49357==    by 0x804A0DB: z_thread_entry (thread_entry.c:29)
==49357==    by 0x805188D: posix_thread_starter (posix_core.c:305)
==49357==    by 0x414467F: start_thread (in /usr/lib/libpthread-2.31.so)
==49357==    by 0x4254829: clone (in /usr/lib/libc-2.31.so)
==49357== 

I also needed to apply the fix at #36284.
Not sure where the issues are, the backtrace does not indicate a problem in networking side.

[jukkar]

The client thread is flooding the system which is causing some issues in TCP because the CONFIG_NET_TCP_TIME_WAIT_DELAY is set to 250ms by default. Because of this, the TCP resources are kept still around after the socket is closed. Everything should be working smoothly even if the device is flooded, but there seems to be some place in the stack that does not handle resource exhaustion properly.

Everything starts to work much better if I add

k_msleep(250);

after the socket close in tcpclient thread.

[chyu313]

Can be replicated with native_posix

The following is how it goes:

1. tcp_work thread: send_timer->tcp_send_process()->tcp_send_process_no_lock()->"peek head pkt in conn->send_queue"
2. context switch to tcp client thread: net_tcp_connect()->tcp_conn_unref()(for ETIMEDOUT)->tcp_send_queue_flush()
3. context switch back to tcp_work thread: tcp_send_process_no_lock()->k_work_reschedule_for_queue()->z_add_timeout()->"append conn->send_timer->timeout to timeout_list"
4. context switch back to tcp client thread: tcp_conn_unref()->memset(conn, 0, sizeof(*conn)), which clears conn->send_timer->timeout structure
5. irq: sys_clock_announce->remove_timeout(), the timeout structure is cleared in step 4, so null pointer access occurs

[kevin0402]

My understanding is if remote TCP server is unreachable (e.g. IP address is wrong) and TCP client in Zephyr is keeping retry to connect, then Zephyr will crash.
If this is true, it would be an serious issue in TCP2 stack especially we are working toward to v2.7 LTS release.

[chyu313]

1. tcp_work thread: send_timer->tcp_send_process()->tcp_send_process_no_lock()->"peek head pkt in conn->send_queue"
2. context switch to tcp client thread: net_tcp_connect()->tcp_conn_unref()(for ETIMEDOUT)->tcp_send_queue_flush()
3. context switch back to tcp_work thread: tcp_send_process_no_lock()->k_work_reschedule_for_queue()->z_add_timeout()->"append conn->send_timer->timeout to timeout_list"
4. context switch back to tcp client thread: tcp_conn_unref()->memset(conn, 0, sizeof(*conn)), which clears conn->send_timer->timeout structure
5. irq: sys_clock_announce->remove_timeout(), the timeout structure is cleared in step 4, so null pointer access occurs

A race condition occurs when tcp_conn_unref() is executed by tcp client thread to release tcp connection while tcp_work thread is running tcp_send_process() in which tcp connection is being processed.

Locking tcp_lock in tcp_send_process() can avoid race condition described above.

static void tcp_send_process(struct k_work *work)
{
	struct tcp *conn = CONTAINER_OF(work, struct tcp, send_timer);
	bool unref;

	k_mutex_lock(&tcp_lock, K_FOREVER);

	k_mutex_lock(&conn->lock, K_FOREVER);

	unref = tcp_send_process_no_lock(conn);

	k_mutex_unlock(&conn->lock);

	k_mutex_unlock(&tcp_lock);

	if (unref) {
		tcp_conn_unref(conn);
	}
}

[github-actions]

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.

[carlescufi]

@tbursztyka do you think this issue is still applicable?

[github-actions]

This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.