Timeout connecting to 127.0.0.53 from sane

cassava · 2023-03-29 15:29:44

There's about 10s delay from running a sane scan command to the scanner starting to do something.
After inspecting the strace output piped through ts, I find the following section:

...
Mar 29 16:50:46 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 8
Mar 29 16:50:46 setsockopt(8, SOL_IP, IP_RECVERR, [1], 4) = 0
Mar 29 16:50:46 connect(8, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
Mar 29 16:50:46 poll([{fd=8, events=POLLOUT}], 1, 0)    = 1 ([{fd=8, revents=POLLOUT}])
Mar 29 16:50:46 sendto(8, "\354#\1 \0\1\0\0\0\0\0\1\00246\00250\00257\00249\7in-addr"..., 53, MSG_NOSIGNAL, NULL, 0) = 53
Mar 29 16:50:51 poll([{fd=8, events=POLLIN}], 1, 5000)  = 0 (Timeout)
Mar 29 16:50:51 poll([{fd=8, events=POLLOUT}], 1, 0)    = 1 ([{fd=8, revents=POLLOUT}])
Mar 29 16:50:51 sendto(8, "\354#\1 \0\1\0\0\0\0\0\1\00246\00250\00257\00249\7in-addr"..., 53, MSG_NOSIGNAL, NULL, 0) = 53
Mar 29 16:50:56 poll([{fd=8, events=POLLIN}], 1, 5000)  = 0 (Timeout)
Mar 29 16:50:56 close(8)
...

Notice that there is a 5000 ms timeout that happens after each sendto.

We're connecting to 127.0.0.53, so systemd-resolved. I checked and it's running and listening:

$ netstat -tulpn | grep 127.0.0.53
tcp        0      0 127.0.0.53:53           0.0.0.0:*               LISTEN      -
udp        0      0 127.0.0.53:53           0.0.0.0:*                           -

I checked resolvectl status:

$ resolvectl status
Global
           Protocols: +LLMNR +mDNS -DNSOverTLS DNSSEC=no/unsupported
    resolv.conf mode: stub
Fallback DNS Servers: 1.1.1.1#cloudflare-dns.com 9.9.9.9#dns.quad9.net 8.8.8.8#dns.google 2606:4700:4700::1111#cloudflare-dns.com 2620:fe::9#dns.quad9.net 2001:4860:4860::8888#dns.google
          DNS Domain: fritz.box

Link 2 (enp0s31f6)
    Current Scopes: none
         Protocols: -DefaultRoute +LLMNR +mDNS -DNSOverTLS DNSSEC=no/unsupported

Link 4 (wlan0)
    Current Scopes: DNS LLMNR/IPv4 LLMNR/IPv6 mDNS/IPv4 mDNS/IPv6
         Protocols: +DefaultRoute +LLMNR +mDNS -DNSOverTLS DNSSEC=no/unsupported
Current DNS Server: 192.168.144.1
       DNS Servers: 192.168.144.1
        DNS Domain: fritz.box

Also looks ok, I used nslookup to check a few global and local names, and they all return immediately.

Does anyone have any idea what might be going on here?

seth · 2023-03-29 20:05:29

nslookup uses resolv, not not dns to resolve the domain (if possible)

drill google.com # ldns package
drill @127.0.0.53 google.com
drill @192.168.144.1 google.com

cassava · 2023-03-29 22:12:20

I tried all of those drill commands, and they all return immediately:

$ drill @127.0.0.53 google.com
;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 35244
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;; google.com.	IN	A

;; ANSWER SECTION:
google.com.	175	IN	A	142.250.186.78

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 25 msec
;; SERVER: 127.0.0.53
;; WHEN: Thu Mar 30 00:10:07 2023
;; MSG SIZE  rcvd: 44

$ drill google.com
;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 31660
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;; google.com.	IN	A

;; ANSWER SECTION:
google.com.	169	IN	A	142.250.186.78

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 0 msec
;; SERVER: 127.0.0.53
;; WHEN: Thu Mar 30 00:10:13 2023
;; MSG SIZE  rcvd: 44

$ drill @192.168.144.1 google.com
;; ->>HEADER<<- opcode: QUERY, rcode: NOERROR, id: 43245
;; flags: qr rd ra ; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
;; QUESTION SECTION:
;; google.com.	IN	A

;; ANSWER SECTION:
google.com.	284	IN	A	142.250.185.142

;; AUTHORITY SECTION:

;; ADDITIONAL SECTION:

;; Query time: 4 msec
;; EDNS: version 0; flags: ; udp: 1452
; PADDING:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
;; SERVER: 192.168.144.1
;; WHEN: Thu Mar 30 00:10:24 2023
;; MSG SIZE  rcvd: 479

cassava · 2023-03-29 22:17:07

Here's some more context:

Command being run:

strace -s 256 scanimage --device-name "brother4:net1;dev0" 2>&1 | ts | tee ~/output.log

Unclipped output section:

Mar 30 00:08:48 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 8
Mar 30 00:08:48 setsockopt(8, SOL_IP, IP_RECVERR, [1], 4) = 0
Mar 30 00:08:48 connect(8, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("127.0.0.53")}, 16) = 0
Mar 30 00:08:48 poll([{fd=8, events=POLLOUT}], 1, 0)    = 1 ([{fd=8, revents=POLLOUT}])
Mar 30 00:08:48 sendto(8, "8?\1 \0\1\0\0\0\0\0\1\00246\00250\00257\00249\7in-addr\4arpa\0\0\f\0\1\0\0)\4\260\0\0\0\0\0\0", 53, MSG_NOSIGNAL, NULL, 0) = 53
Mar 30 00:08:53 poll([{fd=8, events=POLLIN}], 1, 5000)  = 0 (Timeout)
Mar 30 00:08:53 poll([{fd=8, events=POLLOUT}], 1, 0)    = 1 ([{fd=8, revents=POLLOUT}])
Mar 30 00:08:53 sendto(8, "8?\1 \0\1\0\0\0\0\0\1\00246\00250\00257\00249\7in-addr\4arpa\0\0\f\0\1\0\0)\4\260\0\0\0\0\0\0", 53, MSG_NOSIGNAL, NULL, 0) = 53
Mar 30 00:08:58 poll([{fd=8, events=POLLIN}], 1, 5000)  = 0 (Timeout)
Mar 30 00:08:58 close(8)                                = 0

Then it falls back to using the address configured in /etc/opt/brother/scanner/brscan4/brsanenetdevice4.cfg

Mar 30 00:08:58 fcntl(7, F_GETFL)                       = 0x2 (flags O_RDWR)
Mar 30 00:08:58 fcntl(7, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
Mar 30 00:08:58 connect(7, {sa_family=AF_INET, sin_port=htons(54921), sin_addr=inet_addr("192.168.144.254")}, 16) = -1 EINPROGRESS (Operation now in progress)

This is the contents of /etc/opt/brother/scanner/brscan4/brsanenetdevice4.cfg:

DEVICE=Brother_MFC-J5730DW , "MFC-J5730DW" , 0x4f9:0x3d5 , IP-ADDRESS=192.168.144.254

alistairCookie · 2023-03-30 02:36:46

are you using systemd.resolv or /etc/resolv.conf ?

seth · 2023-03-30 06:34:40

drill in-addr.arpa
drill @127.0.0.1 in-addr.arpa # should™ be the same as above
drill @1.1.1.1 in-addr.arpa

Ftr. it looks like sane is reverse looking up a bogus IP, but it's not in your sane config.

Last edited by seth (2023-03-30 06:40:14)

cassava · 2023-03-30 19:57:06

Yes, I've been scouring my whole system for any of those parts, and I can't find anything that would make sense.

I'm using now only a single driver in my SANE `dll.conf`, which is `brother4`, provided by the `brscan4` AUR package.

I am using `systemd-resolved` with the symlink to /run/systemd/resolve/stub-resolv.conf

seth · 2023-03-30 20:06:00

Did you try whether resolving in-addr.arpa or maybe

dig @127.0.0.53 -x 246.250.257.249
dig @1.1.1.1 -x 246.250.257.249
dig -x 246.250.257.249

(I guess that's the IP in the strace) is slow? (drill will not work w/ that IP)

Also post the entire strace (1st link below) - maybe the context helps to understand what's getting us here.

Arch Linux

#1 2023-03-29 15:29:44

Timeout connecting to 127.0.0.53 from sane

#2 2023-03-29 20:05:29

Re: Timeout connecting to 127.0.0.53 from sane

#3 2023-03-29 22:12:20

Re: Timeout connecting to 127.0.0.53 from sane

#4 2023-03-29 22:17:07

Re: Timeout connecting to 127.0.0.53 from sane

#5 2023-03-30 02:36:46

Re: Timeout connecting to 127.0.0.53 from sane

#6 2023-03-30 06:34:40

Re: Timeout connecting to 127.0.0.53 from sane

#7 2023-03-30 19:57:06

Re: Timeout connecting to 127.0.0.53 from sane

#8 2023-03-30 20:06:00

Re: Timeout connecting to 127.0.0.53 from sane

Board footer