dns resolve timeout leads to CPU memory access violation error

[nimarty]

Describe the bug
Zephyr OS crashes when trying to do a DNS resolve. Zephyr runs in QEMU (qemu_x86). zsock_getaddrinfo() from getaddrinfo.c is used.

To Reproduce
Steps to reproduce the behavior:

1. build for qemu_x86 and run
2. simple application sends a dns query from within main() using api mentioned in description.
3. zephyr fatal error

Expected behavior
When the DNS server is not reachable, then the query timeout should not lead to a fatal error.

Impact
Cannot run dns resolver in qemu, which is part of a bigger application which i would like to test in qemu.

Logs and console output

[00:00:03.200,000] <dbg> net_dns_resolve.query_timeout: (sysworkq): Query timeout DNS req 2436 type 1 hash 23545
[00:00:03.200,000] <dbg> net_dns_resolve.dns_resolve_cancel_with_hash: (sysworkq): Cancelling DNS req 2436 (name httpbin.org type 1 hash 23545)
[00:00:03.200,000] <dbg> net_sock_addr.dns_resolve_cb: (sysworkq): dns status: -101
[00:00:03.200,000] <err> os: Page fault at address 0x3 (error code 0x0)
[00:00:03.200,000] <err> os: Linear address not present in page tables
[00:00:03.200,000] <err> os: Access violation: supervisor thread not allowed to read
[00:00:03.200,000] <err> os: PTE: not present
[00:00:03.200,000] <err> os: EAX: 0x00000003, EBX: 0x00000003, ECX: 0x00000050, EDX: 0x00000000
[00:00:03.200,000] <err> os: ESI: 0x00000012, EDI: 0x0015cb0c, EBP: 0x0015cb70, ESP: 0x0015cb64
[00:00:03.210,000] <err> os: EFLAGS: 0x00000046 CS: 0x0008 CR3: 0x00165000
[00:00:03.210,000] <err> os: call trace:
[00:00:03.210,000] <err> os: EIP: 0x001014c6
[00:00:03.210,000] <err> os:      0x00130e1d (0x15cb0c)
[00:00:03.210,000] <err> os:      0x001314dd (0x15cb0c)
[00:00:03.210,000] <err> os:      0x001317b7 (0x15cb0c)
[00:00:03.210,000] <err> os:      0x0010a21f (0x15cb0c)
[00:00:03.210,000] <err> os:      0x0012e566 (0xffffff9b)
[00:00:03.210,000] <err> os:      0x0012e637 (0x13b4c0)
[00:00:03.210,000] <err> os:      0x00102091 (0x1414a8)
[00:00:03.210,000] <err> os:      0x00101e61 (0x141780)
[00:00:03.210,000] <err> os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
[00:00:03.210,000] <err> os: Current thread: 0x1417a0 (sysworkq)
[00:00:03.220,000] <err> os: Halting system

Environment (please complete the following information):

• OS: Linux
• Zephyr v2.4.99-ncs1

[mniestroj]

"Zephyr v2.4.99-ncs1" is not mainline Zephyr. Could you retest with tip of master?

It would be also very useful to provide link to commited code (your fork) that allows to reproduce this bug. Just to speed up reproducing it.

[nimarty]

I updated to the latest Zephyr OS: zephyr-v2.5.0-3535-gf4350a9303e5 and retried to do a dns resolve with qemu_x86.

This time there is a problem while/after receiving ARP response. DNS query was not even sent.

[00:00:01.020,000] <dbg> net_dns_resolve.dns_write: (sysworkq): [0] submitting work to server idx 0 for id 9557 hash 23545
[00:00:01.020,000] <dbg> net_pkt.pkt_alloc_with_buffer: (sysworkq): On iface 0x1602f4 size 29
[00:00:01.020,000] <dbg> net_pkt.pkt_estimate_headers_length: (sysworkq): HDRs length estimation 28
[00:00:01.020,000] <dbg> net_pkt.net_pkt_alloc_buffer_debug: (sysworkq): Data allocation maximum size 57 (requested 29)
[00:00:01.020,000] <dbg> net_pkt.pkt_alloc_buffer: (sysworkq): TDATA (?) [0] frag 0x1497a0 ref 1 (context_alloc_pkt():1363)
[00:00:01.020,000] <dbg> net_pkt.pkt_estimate_headers_length: (sysworkq): HDRs length estimation 28
[00:00:01.020,000] <dbg> net_pkt.net_pkt_write: (sysworkq): pkt 0x1579f0 data 0x1485a0 length 20
[00:00:01.020,000] <dbg> net_pkt.net_pkt_skip: (sysworkq): pkt 0x1579f0 skip 20
[00:00:01.020,000] <dbg> net_pkt.net_pkt_write: (sysworkq): pkt 0x1579f0 data 0x1485b4 length 8
[00:00:01.020,000] <dbg> net_pkt.net_pkt_skip: (sysworkq): pkt 0x1579f0 skip 8
[00:00:01.020,000] <dbg> net_pkt.net_pkt_write: (sysworkq): pkt 0x1579f0 data 0x14b700 length 29
[00:00:01.020,000] <dbg> net_pkt.net_pkt_write: (sysworkq): pkt 0x1579f0 data 0x1485a0 length 20
[00:00:01.020,000] <dbg> net_pkt.net_pkt_skip: (sysworkq): pkt 0x1579f0 skip 20
[00:00:01.020,000] <dbg> net_pkt.net_pkt_skip: (sysworkq): pkt 0x1579f0 skip 12
[00:00:01.020,000] <dbg> net_pkt.net_pkt_skip: (sysworkq): pkt 0x1579f0 skip 8
[00:00:01.020,000] <dbg> net_pkt.net_pkt_write: (sysworkq): pkt 0x1579f0 data 0x1485b4 length 8
[00:00:01.020,000] <dbg> net_pkt.net_pkt_skip: (sysworkq): pkt 0x1579f0 skip 8
[00:00:01.020,000] <dbg> net_if.net_if_tx: (sysworkq): Processing (pkt 0x1579f0, prio 1) network packet iface 0x1602f4/1
[00:00:01.020,000] <dbg> net_arp.arp_entry_find_move_first: (sysworkq): dst 192.0.2.2
[00:00:01.020,000] <dbg> net_arp.arp_entry_find_pending: (sysworkq): dst 192.0.2.2
[00:00:01.020,000] <dbg> net_pkt.pkt_alloc_with_buffer: (sysworkq): On iface 0x1602f4 size 28
[00:00:01.020,000] <dbg> net_pkt.net_pkt_alloc_buffer_debug: (sysworkq): Data allocation maximum size 28 (requested 28)
[00:00:01.020,000] <dbg> net_pkt.pkt_alloc_buffer: (sysworkq): TDATA (?) [0] frag 0x1497b8 ref 1 (arp_prepare():249)
[00:00:01.020,000] <dbg> net_pkt.net_pkt_ref_debug: (<log_strdup alloc failed>): TX [12] pkt 0x1579f0 ref 2 (arp_prepare():274)
[00:00:01.020,000] <dbg> net_arp.arp_entry_register_pending: (<log_strdup alloc failed>): dst <log_strdup alloc failed>
[00:00:01.020,000] <dbg> net_ethernet.ethernet_ll_prepare_on_ipv4: (<log_strdup alloc failed>): Sending arp pkt 0x1579a0 (orig 0x1579f0) to iface 0x1602f4
[00:00:01.020,000] <dbg> net_pkt.net_pkt_unref_debug: (<log_strdup alloc failed>): TX [12] pkt 0x1579f0 ref 1 frags 0x1497a0 (ethernet_ll_prepare_on_ipv4():370)
[00:00:01.020,000] <dbg> net_pkt.net_pkt_get_reserve_data_debug: (<log_strdup alloc failed>): TDATA (?) [0] frag 0x1497d0 ref 1 (ethernet_fill_header():486)
[00:00:01.020,000] <dbg> net_ethernet.ethernet_fill_header: (<log_strdup alloc failed>): iface 0x1602f4 src <log_strdup alloc failed> dst <log_strdup alloc failed> type 0x806 len 14
[00:00:01.020,000] <dbg> net_pkt.net_pkt_frag_insert_debug: (<log_strdup alloc failed>): pkt 0x1579a0 frag 0x1497d0 (ethernet_fill_header:534)
[00:00:01.020,000] <dbg> net_pkt.net_pkt_read: (<log_strdup alloc failed>): pkt 0x1579a0 data 0x14458e length 42
[00:00:01.020,000] <dbg> eth_e1000.e1000_tx: iow32 TDT 0x00000001
[00:00:01.020,000] <dbg> eth_e1000.e1000_tx: tx.sta: 0x01
[00:00:01.020,000] <dbg> net_pkt.net_pkt_frag_unref_debug: (<log_strdup alloc failed>): TDATA (?) [0] frag 0x1497d0 ref 0 (ethernet_remove_l2_header():566)
[00:00:01.020,000] <dbg> net_pkt.net_pkt_unref_debug: (<log_strdup alloc failed>): TX [12] pkt 0x1579a0 ref 0 frags 0x1497b8 (ethernet_send():685)
[00:00:01.020,000] <dbg> net_pkt.net_pkt_unref_debug: (<log_strdup alloc failed>): TDATA (?) [0] frag 0x1497b8 ref 0 frags (nil) (ethernet_send():685)
[00:00:01.020,000] <dbg> net_pkt.net_pkt_frag_unref_debug: (<log_strdup alloc failed>): TDATA (?) [0] frag 0x1497b8 ref 0 (net_pkt_unref_debug():586)
[00:00:01.020,000] <dbg> eth_e1000.e1000_isr: ior32 ICR 0x00000043
[00:00:01.020,000] <dbg> eth_e1000.e1000_rx: rx.sta: 0x07
[00:00:01.020,000] <dbg> net_pkt.pkt_alloc_with_buffer: (<log_strdup alloc failed>): On iface 0x1602f4 size 60
[00:00:01.020,000] <dbg> net_pkt.net_pkt_alloc_buffer_debug: (<log_strdup alloc failed>): Data allocation maximum size 60 (requested 60)
[00:00:01.020,000] <dbg> net_pkt.pkt_alloc_buffer: (<log_strdup alloc failed>): RDATA (?) [0] frag 0x14ad00 ref 1 (e1000_rx():164)
[00:00:01.020,000] <dbg> net_pkt.net_pkt_write: (<log_strdup alloc failed>): pkt 0x157e50 data 0x144b6a length 60
[00:00:01.020,000] <dbg> net_core.net_recv_data: (<log_strdup alloc failed>): prio 0 iface 0x1602f4 pkt 0x157e50 len 60
[00:00:01.020,000] <err> os: General protection fault (code 0xad08)
[00:00:01.020,000] <err> os: EAX: 0x0015af80, EBX: 0x00000206, ECX: 0x00146038, EDX: 0x00146020
[00:00:01.020,000] <err> os: ESI: 0x001602f4, EDI: 0x00135bc7, EBP: 0x0015af68, ESP: 0x0015af54
[00:00:01.020,000] <err> os: EFLAGS: 0x00000046 CS: 0x0008 CR3: 0x00166000
[00:00:01.020,000] <err> os: call trace:
[00:00:01.020,000] <err> os: EIP: 0x00100697
[00:00:01.020,000] <err> os:      corrupted? (bp=0x15af68)
[00:00:01.020,000] <err> os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
[00:00:01.020,000] <err> os: Current thread: 0x146a20 (<log_strdup alloc failed>)
[00:00:01.060,000] <err> os: Halting system

[mniestroj]

@nimarty Thanks! Could you commit exact configuration and code that results in this crash and send a link? Or at least attach configuration and void main() body?

[nimarty]

@mniestroj Today I tried the dns_resolve sample with qemu_x86. This worked. So probably there's something wrong with the code I use in my main application. I'll try to investigate on that and update the issue asap.

[jukkar]

I tried the dns_resolve sample and I did not see any crashes in the application itself. Noticed a crash in net-shell when invoking net dns command. I will send a fix shortly.

[nimarty]

I managed to create a public example which demonstrates the problem:
https://github.com/endresshauser-lp/iiot-qemu_x86-samples-dnsResolvePlayground
Description on how to build and run the example can be found within the repo

[jukkar]

Your sample application did not crash with following changes:

diff --git a/dnsresolve/src/main.c b/dnsresolve/src/main.c
index 5fd4cb6..0b3316d 100644
--- a/dnsresolve/src/main.c
+++ b/dnsresolve/src/main.c
@@ -65,6 +65,7 @@ static void run_request(struct k_work *work) {
 void main(void) {
 
     dns_init();
-    k_delayed_work_init(&dns_resolve_work, run_request);
-    k_delayed_work_submit(&dns_resolve_work, K_SECONDS(1));
-}
\ No newline at end of file
+    run_request(NULL);
+//    k_delayed_work_init(&dns_resolve_work, run_request);
+//    k_delayed_work_submit(&dns_resolve_work, K_SECONDS(1));
+}

Note that the k_delayed_work API you are using here is deprecated and should be converted to use newer k_delayable_work instead.
But for the crash issue when running from system workqueue, I thought it might be the system workqueue size as it is only 1024 bytes by default, but after increasing it to 4096 the crash remained.

[jukkar]

BTW, you should not run a blocking call like getaddrinfo() from system workqueue as it blocks the workqueue from running and might be actually the real culprit here.

[nimarty]

@jukkar Thank you very much for investigating and your suggestions. I'll see if I can apply those changes to our application asap.

[nimarty]

@jukkar I applied your changes and it works now. When doing dns resolving from main thread or from within separately created thread
K_THREAD_DEFINE(dns_resolver_thread, 2048, run_request, NULL, NULL, NULL, 5, 0, 5);
the error does not appear anymore. When reducing the thread's stack size down to 1024 I get a page fault, I guess the stack is too small in this case.
So your suggestions to not call any blocking functions from within system workqueue solves the problem for me.