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

sock_dns: implement DNS cache #17680

Merged
merged 2 commits into from
Jul 15, 2022
Merged

Conversation

benpicco
Copy link
Contributor

Contribution description

If a domain is used multiple times, RIOT will issue a new DNS query each time. This can add unwanted network overhead and latency, so caching DNS entries can be desirable.

If the cache is full, the first entry to expire will be evicted.

Testing procedure

The DNS cache is enabled with

USEMODULE += sock_dns_cache
> ping riot-os.org
2022-02-19 14:36:58,953 # dns_cache miss
2022-02-19 14:36:58,990 # dns_cache: lifetime of riot-os.org is 86227 s
2022-02-19 14:36:58,992 # dns_cache[0] add cache entry
2022-02-19 14:36:59,029 # 12 bytes from 2001:67c:254:b0b0::1: icmp_seq=0 ttl=56 time=30.365 ms
2022-02-19 14:37:00,032 # 12 bytes from 2001:67c:254:b0b0::1: icmp_seq=1 ttl=56 time=33.197 ms
2022-02-19 14:37:01,039 # 12 bytes from 2001:67c:254:b0b0::1: icmp_seq=2 ttl=56 time=40.015 ms
2022-02-19 14:37:01,039 # 
2022-02-19 14:37:01,042 # --- riot-os.org PING statistics ---
2022-02-19 14:37:01,047 # 3 packets transmitted, 3 packets received, 0% packet loss
2022-02-19 14:37:01,051 # round-trip min/avg/max = 30.365/34.525/40.015 ms
> ping google.com
2022-02-19 14:37:05,145 # dns_cache miss
2022-02-19 14:37:05,204 # dns_cache: lifetime of google.com is 38 s
2022-02-19 14:37:05,206 # dns_cache[1] add cache entry
2022-02-19 14:37:05,253 # 12 bytes from 2a00:1450:4001:82b::200e: icmp_seq=0 ttl=58 time=40.132 ms
2022-02-19 14:37:06,253 # 12 bytes from 2a00:1450:4001:82b::200e: icmp_seq=1 ttl=58 time=40.389 ms
2022-02-19 14:37:07,257 # 12 bytes from 2a00:1450:4001:82b::200e: icmp_seq=2 ttl=58 time=44.207 ms
2022-02-19 14:37:07,257 # 
2022-02-19 14:37:07,260 # --- google.com PING statistics ---
2022-02-19 14:37:07,265 # 3 packets transmitted, 3 packets received, 0% packet loss
2022-02-19 14:37:07,269 # round-trip min/avg/max = 40.132/41.576/44.207 ms
> ping fast.com
2022-02-19 14:37:09,896 # dns_cache miss
2022-02-19 14:37:09,954 # dns_cache: lifetime of fast.com is 20 s
2022-02-19 14:37:09,957 # dns_cache[2] add cache entry
2022-02-19 14:37:10,003 # 12 bytes from 2a02:26f0:7100:2a9::24fe: icmp_seq=0 ttl=58 time=39.065 ms
2022-02-19 14:37:11,002 # 12 bytes from 2a02:26f0:7100:2a9::24fe: icmp_seq=1 ttl=58 time=38.311 ms
2022-02-19 14:37:12,003 # 12 bytes from 2a02:26f0:7100:2a9::24fe: icmp_seq=2 ttl=58 time=39.651 ms
2022-02-19 14:37:12,003 # 
2022-02-19 14:37:12,006 # --- fast.com PING statistics ---
2022-02-19 14:37:12,011 # 3 packets transmitted, 3 packets received, 0% packet loss
2022-02-19 14:37:12,015 # round-trip min/avg/max = 38.311/39.009/39.651 ms
> ping heise.de
2022-02-19 14:37:15,824 # dns_cache miss
2022-02-19 14:37:15,855 # dns_cache: lifetime of heise.de is 85899 s
2022-02-19 14:37:15,858 # dns_cache[3] add cache entry
2022-02-19 14:37:15,908 # 12 bytes from 2a02:2e0:3fe:1001:302::: icmp_seq=0 ttl=55 time=43.314 ms
2022-02-19 14:37:16,908 # 12 bytes from 2a02:2e0:3fe:1001:302::: icmp_seq=1 ttl=55 time=44.007 ms
2022-02-19 14:37:17,909 # 12 bytes from 2a02:2e0:3fe:1001:302::: icmp_seq=2 ttl=55 time=44.313 ms
2022-02-19 14:37:17,909 # 
2022-02-19 14:37:17,911 # --- heise.de PING statistics ---
2022-02-19 14:37:17,917 # 3 packets transmitted, 3 packets received, 0% packet loss
2022-02-19 14:37:17,921 # round-trip min/avg/max = 43.314/43.878/44.313 ms
> ping golem.de
2022-02-19 14:37:29,016 # dns_cache miss
2022-02-19 14:37:29,117 # dns_cache: lifetime of golem.de is 300 s
2022-02-19 14:37:29,121 # dns_cache: evict first entry to expire
2022-02-19 14:37:29,123 # dns_cache[2] add cache entry
2022-02-19 14:37:29,163 # 12 bytes from 2a00:13c8:f5::f:4b3d:148: icmp_seq=0 ttl=57 time=32.703 ms
2022-02-19 14:37:30,160 # 12 bytes from 2a00:13c8:f5::f:4b3d:148: icmp_seq=1 ttl=57 time=30.124 ms
2022-02-19 14:37:31,160 # 12 bytes from 2a00:13c8:f5::f:4b3d:148: icmp_seq=2 ttl=57 time=29.833 ms
2022-02-19 14:37:31,160 # 
2022-02-19 14:37:31,163 # --- golem.de PING statistics ---
2022-02-19 14:37:31,168 # 3 packets transmitted, 3 packets received, 0% packet loss
2022-02-19 14:37:31,172 # round-trip min/avg/max = 29.833/30.886/32.703 ms
> ping golem.de
2022-02-19 14:37:38,728 # dns_cache[2] hit
2022-02-19 14:37:38,768 # 12 bytes from 2a00:13c8:f5::f:4b3d:148: icmp_seq=0 ttl=57 time=33.294 ms
2022-02-19 14:37:39,764 # 12 bytes from 2a00:13c8:f5::f:4b3d:148: icmp_seq=1 ttl=57 time=29.464 ms
2022-02-19 14:37:40,757 # 12 bytes from 2a00:13c8:f5::f:4b3d:148: icmp_seq=2 ttl=57 time=22.616 ms
2022-02-19 14:37:40,757 # 
2022-02-19 14:37:40,760 # --- golem.de PING statistics ---
2022-02-19 14:37:40,765 # 3 packets transmitted, 3 packets received, 0% packet loss
2022-02-19 14:37:40,770 # round-trip min/avg/max = 22.616/28.458/33.294 ms

Issues/PRs references

@benpicco benpicco requested a review from JKRhb February 19, 2022 13:40
@github-actions github-actions bot added Area: build system Area: Build system Area: network Area: Networking Area: sys Area: System labels Feb 19, 2022
@benpicco benpicco removed the Area: build system Area: Build system label Feb 19, 2022
Copy link
Member

@JKRhb JKRhb left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good to me in general :) See a couple of comments below.

sys/net/application_layer/dns/msg.c Outdated Show resolved Hide resolved
sys/net/application_layer/sock_dns/dns.c Show resolved Hide resolved
sys/net/application_layer/sock_dns/dns_cache.c Outdated Show resolved Hide resolved
sys/net/application_layer/sock_dns/dns_cache.c Outdated Show resolved Hide resolved
Copy link
Contributor

@HendrikVE HendrikVE left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice one, I should have a look at the new PRs more often. I tested this PR with #17494 (without the topmost fixup commit) on esp32-wroom-32 so I can can query a specific IP versions. Works like a charm, but there are two small compilation issues for me.

sys/net/application_layer/sock_dns/dns_cache.c Outdated Show resolved Hide resolved
@HendrikVE
Copy link
Contributor

Compiles now for all of my platforms. But I noticed something that does not seem quite right:

> dns server 4 8.8.8.8
2022-03-26 18:45:28,692 # dns server 4 8.8.8.8
> dns request 4 google.co
2022-03-26 18:45:41,967 # dns request 4 google.co
2022-03-26 18:45:41,971 # dns_cache miss
2022-03-26 18:45:42,000 # dns_cache: lifetime of google.co is 300 s
2022-03-26 18:45:42,003 # dns_cache[0] add cache entry
2022-03-26 18:45:42,006 # google.co resolves to 142.250.74.206
> dns request 4 google.com
2022-03-26 18:45:47,656 # dns request 4 google.com
2022-03-26 18:45:47,659 # dns_cache miss
2022-03-26 18:45:47,684 # dns_cache: lifetime of google.com is 179 s
2022-03-26 18:45:47,687 # dns_cache[1] add cache entry
2022-03-26 18:45:47,690 # google.com resolves to 142.250.185.78
> dns request 4 google.comm
2022-03-26 18:46:05,716 # dns request 4 google.comm
2022-03-26 18:46:05,719 # dns_cache[1] hit
2022-03-26 18:46:05,723 # google.comm resolves to 142.250.185.78
> dns request 4 google.commm
2022-03-26 18:46:12,194 # dns request 4 google.commm
2022-03-26 18:46:12,197 # dns_cache miss
2022-03-26 18:46:12,241 # error resolving google.commm
> dns request 4 google.commmm
2022-03-26 18:46:16,052 # dns request 4 google.commmm
2022-03-26 18:46:16,055 # dns_cache miss
2022-03-26 18:46:16,097 # error resolving google.commmm
> dns request 4 google.commm
2022-03-26 18:46:17,677 # dns request 4 google.commm
2022-03-26 18:46:17,680 # dns_cache miss
2022-03-26 18:46:17,722 # error resolving google.commm
> dns request 4 google.comm
2022-03-26 18:46:18,637 # dns request 4 google.comm
2022-03-26 18:46:18,641 # dns_cache[1] hit
2022-03-26 18:46:18,644 # google.comm resolves to 142.250.185.78
> dns request 4 google.com
2022-03-26 18:46:20,534 # dns request 4 google.com
2022-03-26 18:46:20,537 # dns_cache[1] hit
2022-03-26 18:46:20,541 # google.com resolves to 142.250.185.78
>

google.comm should be a cache miss, but it is considered a hit as it seems to be evaluated as google.com while this should do a dns request and fail thereby.

@benpicco
Copy link
Contributor Author

Uh good catch!
Should be fixed now.

@HendrikVE
Copy link
Contributor

Should be fixed now.

Yep, can confirm. Let's see what murdock thinks about it.

@HendrikVE HendrikVE added the CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR label Mar 26, 2022
@benpicco benpicco removed the CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR label Mar 26, 2022
@benpicco
Copy link
Contributor Author

There is still no test application so no compile test :(

@HendrikVE
Copy link
Contributor

Whoops true 😄 The sock_dns_mock pseudomodule I introduced in #16853 could be split out in its own PR and it could be extended with more pre-configured IPs such that it makes sense to test with the cache?

@benpicco
Copy link
Contributor Author

benpicco commented Apr 3, 2022

I now added a unit test for the module.

@HendrikVE
Copy link
Contributor

I think the test should also cover that the cache eviction is working properly. The case of setting IPv6 for a domain but requesting IPv4 is already included, the mirrored case would also be nice to include.

@benpicco benpicco added the CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR label May 11, 2022
@miri64
Copy link
Member

miri64 commented May 12, 2022

Not necessarily needed to be done in this PR and wrt to #16705 I admit that I have an agenda ;-P, but I see some overlap between this cache and nanocoap_cache. Do you think it makes sense to have some underlying common ADT and allocation pool that both caches could use?

@benpicco benpicco force-pushed the sock_dns_cache branch 2 times, most recently from b51ba34 to 48d4b17 Compare June 15, 2022 20:26
@benpicco benpicco added CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR and removed CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR labels Jul 13, 2022
@github-actions github-actions bot added the Area: CoAP Area: Constrained Application Protocol implementations label Jul 13, 2022
@miri64
Copy link
Member

miri64 commented Jul 14, 2022

Happy happy API change and another user of dns_msg 😅

@miri64
Copy link
Member

miri64 commented Jul 14, 2022

About the long unittests: Can you reproduce this locally? Maybe for some reason there is some spin- or deadlock?

@benpicco
Copy link
Contributor Author

I don't see the timeout when I run the test locally.

@miri64
Copy link
Member

miri64 commented Jul 14, 2022

I don't see the timeout when I run the test locally.

Mh but the tests get stuck for a while for me when I run it locally...

TEST_ASSERT_EQUAL_INT(0, sock_dns_cache_query("example.comm", &addr_out, AF_INET6));
TEST_ASSERT_EQUAL_INT(0, sock_dns_cache_query("example.co", &addr_out, AF_INET6));

ztimer_sleep(ZTIMER_MSEC, 2000);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we really have to have 2 seconds here? Can't you mock the now value or timeout some how to enforce a timeout?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Alternatively, for testing you could make the clock resolution of sock_dns_cache_add()'s ttl configurable, and have it in milliseconds specifically for the tests.

@miri64
Copy link
Member

miri64 commented Jul 14, 2022

I don't see the timeout when I run the test locally.

Mh but the tests get stuck for a while for me when I run it locally...

Here's the full output from my local runs
$ make -C tests/unittests/ -j flash test
make: Entering directory '/home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests'
/home/mlenders/Repositories/RIOT-OS/RIOT/makefiles/kconfig.mk:118: Warning! SHOULD_RUN_KCONFIG is not set but a previous configuration file was detected (did you run `make menuconfig`?). Kconfig will run regardless.
/home/mlenders/Repositories/RIOT-OS/RIOT/makefiles/kconfig.mk:118: Warning! SHOULD_RUN_KCONFIG is not set but a previous configuration file was detected (did you run `make menuconfig`?). Kconfig will run regardless.
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/pkg/tiny-asn1/ 
Building application "tests_unittests" for "native" with MCU "native".

"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/build/pkg/tiny-asn1/src -f /home/mlenders/Repositories/RIOT-OS/RIOT/Makefile.base MODULE=tiny-asn1
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/boards/common/init
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/boards/native
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/core
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/core/lib
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/cpu/native
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/drivers
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-analog_util
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-base64
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-bcd
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/boards/native/drivers
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-bitfield
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/drivers/mtd
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/drivers/periph_common
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/drivers/rtt_rtc
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-bloom
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/analog_util
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-bluetil
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/drivers/saul
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-checksum
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/base64
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/drivers/sht1x
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-chunked_ringbuffer
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/bitfield
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-clif
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/bloom
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/checksum
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-color
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-core
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-credman
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/chunked_ringbuffer
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/clif
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/color
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-div
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-ecc
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/crypto
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/div
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-fib
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-fib_sr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/ecc
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-fmt
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/embunit
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-frac
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/event
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-gcoap
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-gnrc_ipv6
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-gnrc_ipv6_hdr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/evtimer
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-gnrc_ipv6_nib
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/fmt
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/frac
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/cpu/native/mtd
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-gnrc_mac_internal
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/fs/constfs
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/hashes
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/iolist
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-gnrc_netif_pktq
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-gnrc_sixlowpan_frag_vrb
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/cpu/native/periph
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/cpu/native/stdio_native
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/luid
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-gnrc_udp
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-hashes
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/matstat
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-ieee802154
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/application_layer/dns
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-inet_csum
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/cpu/native/vfs
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-ipv4_addr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/application_layer/gcoap
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-ipv6_addr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/application_layer/nanocoap
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-ipv6_hdr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/application_layer/sock_dns
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/ble/bluetil
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-kernel_defines
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-luid
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/credman
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-matstat
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/crosslayer/inet_csum
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-mtd
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/crosslayer/netopt
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-nanocoap
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/ble/bluetil/bluetil_addr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-nanocoap_cache
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/link_layer/csma_sender
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-netopt
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/link_layer/ieee802154
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-netreg
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/link_layer/l2util
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/netif
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/link_layer/mac
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-phydat
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-pkt
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/network_layer/fib
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-pktbuf
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/netapi
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/network_layer/icmpv6
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/netif
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-pktqueue
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/network_layer/ipv4/addr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-printf_float
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/netreg
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/network_layer/ipv6/addr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-priority_pktqueue
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/network_layer/icmpv6
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-rtc
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/network_layer/ipv6/hdr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/network_layer/sixlowpan
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/network_layer/ipv6
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-rtt_rtc
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/sock
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/sock/async/event
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-saul_reg
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/network_layer/ipv6/hdr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/transport_layer/udp
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/od
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-scanf_float
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/network_layer/ipv6/nib
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-seq
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/phydat
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/network_layer/ndp
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-sht1x
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/posix/inet
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/network_layer/sixlowpan
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/netif/hdr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-sixlowpan
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/network_layer/sixlowpan/ctx
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/random
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-sixlowpan_ctx
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/rtc_utils
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/saul_reg
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/network_layer/sixlowpan/frag/fb
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-sixlowpan_sfr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/network_layer/sixlowpan/frag/vrb
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/seq
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/network_layer/sixlowpan/nd
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-sock_dns_cache
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/test_utils/interactive_sync
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/test_utils/print_stack_usage
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/pkt
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-sock_util
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/test_utils/result_output
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/pktbuf
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-timex
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/timex
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/pktbuf_static
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/priority_pktqueue
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-tsrb
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/sock
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-turo
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/sock/udp
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/tsrb
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/transport_layer/udp
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-uri_parser
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/universal_address
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/test_utils/result_output/check
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-ut_process
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/uri_parser
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/ut_process
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/net/gnrc/netif/pktq
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-uuid
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/uuid
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/vfs
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/ztimer
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-vfs
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/sys/ztimer64
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-zptr
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-ztimer
"make" -C /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-ztimer64
   text	   data	    bss	    dec	    hex	filename
1829668	 210704	 130512	2170884	 212004	/home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/bin/native/tests_unittests.elf
r
/home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/bin/native/tests_unittests.elf /dev/ttyACM0 
RIOT native interrupts/signals initialized.
RIOT native board initialized.
RIOT native hardware initialization complete.

main(): This is RIOT! (Version: 2022.07-devel-1030-gbb0dc-HEAD)
Help: Press s to start test, r to print it is ready
READY
s
START
.........................................................................................................................................................................==325133==WARNING: ASan doesn't fully support makecontext/swapcontext functions and may produce false positives in some cases!
.....................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................Timeout in expect script at "child.expect(r'OK \((\d+) tests\)', timeout=timeout)" (dist/pythonlibs/testrunner/__init__.py:57)

It get's stuck in ztimer_sleep() somehow.

#0  0x0817ac70 in _del_entry_from_list (clock=clock@entry=0x823cb60 <_ztimer_periph_timer>, entry=entry@entry=0x825cb44 <_ztimer_convert_frac_msec+36>) at /home/mlenders/Repositories/RIOT-OS/RIOT/sys/ztimer/core.c:246
#1  0x0817b555 in ztimer_set (clock=0x823cb60 <_ztimer_periph_timer>, timer=0x825cb44 <_ztimer_convert_frac_msec+36>, val=2000000) at /home/mlenders/Repositories/RIOT-OS/RIOT/sys/ztimer/core.c:97
#2  0x08179aae in ztimer_convert_frac_op_set (z=0x825cb20 <_ztimer_convert_frac_msec>, val=2000) at /home/mlenders/Repositories/RIOT-OS/RIOT/sys/ztimer/convert_frac.c:55
#3  0x0817b65a in ztimer_set (clock=0x825cb20 <_ztimer_convert_frac_msec>, timer=0x82429d0 <main_stack+15280>, val=2000) at /home/mlenders/Repositories/RIOT-OS/RIOT/sys/ztimer/core.c:117
#4  0x0817c66f in ztimer_sleep (clock=<optimized out>, duration=<optimized out>) at /home/mlenders/Repositories/RIOT-OS/RIOT/sys/ztimer/util.c:58
#5  0x08157872 in test_dns_cache_add () at /home/mlenders/Repositories/RIOT-OS/RIOT/tests/unittests/tests-sock_dns_cache/tests-sock_dns_cache.c:35

@miri64
Copy link
Member

miri64 commented Jul 14, 2022

:-/

>>> print list
$1 = (ztimer_base_t *) 0x825ca28 <_ztimer64_usec+8>
>>> print list->next
$2 = (ztimer_base_t *) 0x825ca28 <_ztimer64_usec+8>
>>> print list->next->next
$3 = (ztimer_base_t *) 0x825ca28 <_ztimer64_usec+8>

@miri64
Copy link
Member

miri64 commented Jul 14, 2022

@benpicco: for your local tests: did you run all the unittests or just the sock_dns_cache tests isolated?

@benpicco
Copy link
Contributor Author

Uh good point, when I run all the tests I also see the hang.

@benpicco
Copy link
Contributor Author

The sleep does not hang when I use ZTIMER_USEC

@miri64
Copy link
Member

miri64 commented Jul 15, 2022

Would still prefer a solution that does not slow down the unittests by 2 seconds, but won't block.

@benpicco
Copy link
Contributor Author

I think 2s isn't so bad in the grand scheme of things.
AFAIU the mock ztimer is then a separate clock, so it wouldn't work for the ztimer_now(ZTIMER_MSEC) call inside the dns cache - or am I missing something @kaspar030?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area: build system Area: Build system Area: CoAP Area: Constrained Application Protocol implementations Area: network Area: Networking Area: sys Area: System Area: tests Area: tests and testing framework CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants