Bug 2228585

Summary: systemd-resolved fails to start properly
Product: [Fedora] Fedora Reporter: Arne Ahrend <aahrend>
Component: systemdAssignee: systemd-maint
Status: NEW --- QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 38CC: fedoraproject, filbranden, jmigacz, lnykryn, msekleta, ryncsn, systemd-maint, yuwatana, zbyszek
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
journalctl -u systemd-resolved.service output with systemd.log_level=debug none

Description Arne Ahrend 2023-08-02 18:42:20 UTC
systemd-resolved 253.7-1.fc38 no longer populates /run/systemd/resolve/ on startup, although the service is enabled. Manually calling resolvectl status resolves the issue immediately.

Reproducible: Always

Steps to Reproduce:
1. Boot up system and log in
2. ls -l /etc/resolv.conf  /run/systemd/resolve/ to show dangling link and empty dir
2. Open a terminal window and pinging any site by DNS name (e.g. kernel.org) fails
3. call resolvectl. This gives good output and immediately solves the issue
Actual Results:  
Manual call to resolvectl needed to get functional network name resolution.

Expected Results:  
Fully functional network name resolution automatically enabled at boot.

Comment 1 Arne Ahrend 2023-08-02 18:50:57 UTC
Prior to calling resolvectl:
systemctl status systemd-resolved.service 
× systemd-resolved.service - Network Name Resolution
     Loaded: loaded (/usr/lib/systemd/system/systemd-resolved.service; enabled; preset: enabled)
    Drop-In: /usr/lib/systemd/system/service.d
             └─10-timeout-abort.conf
     Active: failed (Result: exit-code) since Wed 2023-08-02 20:44:53 CEST; 1min 13s ago
       Docs: man:systemd-resolved.service(8)
             man:org.freedesktop.resolve1(5)
             https://www.freedesktop.org/wiki/Software/systemd/writing-network-configuration-managers
             https://www.freedesktop.org/wiki/Software/systemd/writing-resolver-clients
    Process: 779 ExecStart=/usr/lib/systemd/systemd-resolved (code=exited, status=1/FAILURE)
   Main PID: 779 (code=exited, status=1/FAILURE)
      Error: 13 (Keine Berechtigung)
        CPU: 132ms

Aug 02 20:44:53 phoenix.fritz.box systemd[1]: systemd-resolved.service: Scheduled restart job, restart counter is at 5.
Aug 02 20:44:53 phoenix.fritz.box systemd[1]: Stopped systemd-resolved.service - Network Name Resolution.
Aug 02 20:44:53 phoenix.fritz.box systemd[1]: systemd-resolved.service: Start request repeated too quickly.
Aug 02 20:44:53 phoenix.fritz.box systemd[1]: systemd-resolved.service: Failed with result 'exit-code'.
Aug 02 20:44:53 phoenix.fritz.box systemd[1]: Failed to start systemd-resolved.service - Network Name Resolution.
Aug 02 20:44:57 phoenix.fritz.box systemd[1]: systemd-resolved.service: Start request repeated too quickly.
Aug 02 20:44:57 phoenix.fritz.box systemd[1]: systemd-resolved.service: Failed with result 'exit-code'.
Aug 02 20:44:57 phoenix.fritz.box systemd[1]: Failed to start systemd-resolved.service - Network Name Resolution.


After calling resolvectl:
systemctl status systemd-resolved.service 
● systemd-resolved.service - Network Name Resolution
     Loaded: loaded (/usr/lib/systemd/system/systemd-resolved.service; enabled; preset: enabled)
    Drop-In: /usr/lib/systemd/system/service.d
             └─10-timeout-abort.conf
     Active: active (running) since Wed 2023-08-02 20:46:39 CEST; 3min 15s ago
       Docs: man:systemd-resolved.service(8)
             man:org.freedesktop.resolve1(5)
             https://www.freedesktop.org/wiki/Software/systemd/writing-network-configuration-managers
             https://www.freedesktop.org/wiki/Software/systemd/writing-resolver-clients
   Main PID: 3330 (systemd-resolve)
     Status: "Processing requests..."
      Tasks: 1 (limit: 38289)
     Memory: 5.0M
        CPU: 122ms
     CGroup: /system.slice/systemd-resolved.service
             └─3330 /usr/lib/systemd/systemd-resolved

Aug 02 20:46:39 phoenix.fritz.box systemd[1]: Starting systemd-resolved.service - Network Name Resolution...
Aug 02 20:46:39 phoenix.fritz.box systemd-resolved[3330]: Positive Trust Anchors:
Aug 02 20:46:39 phoenix.fritz.box systemd-resolved[3330]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
Aug 02 20:46:39 phoenix.fritz.box systemd-resolved[3330]: Negative trust anchors: home.arpa 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in>
Aug 02 20:46:39 phoenix.fritz.box systemd-resolved[3330]: Using system hostname 'phoenix.fritz.box'.
Aug 02 20:46:39 phoenix.fritz.box systemd[1]: Started systemd-resolved.service - Network Name Resolution.
Aug 02 20:46:39 phoenix.fritz.box systemd-resolved[3330]: enp0s31f6: Bus client set search domain list to: fritz.box
Aug 02 20:46:39 phoenix.fritz.box systemd-resolved[3330]: enp0s31f6: Bus client set default route setting: yes
Aug 02 20:46:39 phoenix.fritz.box systemd-resolved[3330]: enp0s31f6: Bus client set DNS server list to: 192.168.48.1, fd00::3681:c4ff:feb0:e17a, 2003:cb:5717>
Aug 02 20:47:04 phoenix.fritz.box systemd-resolved[3330]: Using degraded feature set UDP instead of UDP+EDNS0 for DNS server 192.168.48.1.

Comment 2 Jacek Migacz 2023-08-07 11:45:03 UTC
I'm not able to reproduce it.

I'm booting fresh f38 with systemd-253.7-1.

# ls -l /etc/resolv.conf
lrwxrwxrwx. 1 root root 39 Aug  1 03:28 /etc/resolv.conf -> ../run/systemd/resolve/stub-resolv.conf

# ls -a /run/systemd/resolve/
.  ..  io.systemd.Resolve  io.systemd.Resolve.Monitor  netif  resolv.conf  stub-resolv.conf

Comment 3 Jacek Migacz 2023-08-07 12:22:58 UTC
@Arne,

Please provide more detailed logs of systemd-resolved.

1. Enable debug log level for systemd-resolved service:
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
[Service]
Environment=SYSTEMD_LOG_LEVEL=debug
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

2. Get the logs:
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
journalctl -u systemd-resolved
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Thanks!

Comment 4 Arne Ahrend 2023-08-07 19:36:17 UTC
Created attachment 1982211 [details]
journalctl -u systemd-resolved.service output with systemd.log_level=debug

Comment 5 Arne Ahrend 2023-08-07 19:39:56 UTC
Lines 1-856 in the log are before manually typing "resolvectl", lines 857-end after calling resolvectl.