Fresh installation stuck 8 minutes at boot

Hi everyone,

i did a fresh installation of IPFire 2.25 (x86_64) on my Hyper-V Server 2016 (Gen1 VM).
The system took 8 minutes to boot after the line “Setting up Pakfire Package Manager…”

I didn’t find much information in the logfiles. I think it has something to do with either the unbound service or the openvpn net2net connection. Maybe the problem only occurs on the x64 architecture beacuse I’m currently running the same version at x86 on the same server and there is no such problem.

I marked the 8 minutes interruption with ------------------------------

Jun 21 02:07:04 ipfire dhcpcd[5358]: red0: releasing lease of xxx.xxx.xxx.xxx
Jun 21 02:07:04 ipfire dhcpcd[6202]: ps_inet_recvmsgpsp: Network is unreachable
Jun 21 02:07:04 ipfire dhcpcd[5358]: red0: deleting route to xxx.xxx.xxx.0/24
Jun 21 02:07:04 ipfire dhcpcd[5358]: red0: deleting default route via xxx.xxx.xxx.1
Jun 21 02:07:04 ipfire dhcpcd.exe[6659]: red0 has been brought down (STOP)
Jun 21 02:07:04 ipfire openvpnserver[6061]: event_wait : Interrupted system call (code=4)
Jun 21 02:07:04 ipfire openvpnserver[6061]: /sbin/ip route del 10.46.19.0/24
Jun 21 02:07:04 ipfire N2N[6118]: event_wait : Interrupted system call (code=4)
Jun 21 02:07:04 ipfire N2N[6118]: /sbin/ip route del 192.168.20.0/24
Jun 21 02:07:04 ipfire openvpnserver[6061]: ERROR: Linux route delete command failed: external program exited with error status: 2
Jun 21 02:07:04 ipfire openvpnserver[6061]: /sbin/ip route del 10.46.18.0/24
Jun 21 02:07:04 ipfire N2N[6118]: ERROR: Linux route delete command failed: external program exited with error status: 2
Jun 21 02:07:04 ipfire N2N[6118]: Closing TUN/TAP interface
Jun 21 02:07:04 ipfire N2N[6118]: /sbin/ip addr del dev tun1 local 10.34.27.1 peer 10.34.27.2
Jun 21 02:07:04 ipfire openvpnserver[6061]: ERROR: Linux route delete command failed: external program exited with error status: 2
Jun 21 02:07:04 ipfire openvpnserver[6061]: Closing TUN/TAP interface
Jun 21 02:07:04 ipfire openvpnserver[6061]: /sbin/ip addr del dev tun0 local 10.46.18.1 peer 10.46.18.2
Jun 21 02:07:04 ipfire N2N[6118]: Linux ip addr del failed: external program exited with error status: 2
Jun 21 02:07:05 ipfire openvpnserver[6061]: Linux ip addr del failed: external program exited with error status: 2
Jun 21 02:07:05 ipfire N2N[6118]: SIGTERM[hard,] received, process exiting
Jun 21 02:07:05 ipfire openvpnserver[6061]: SIGTERM[hard,] received, process exiting
Jun 21 02:07:05 ipfire dhcpcd[5358]: dhcpcd exited
Jun 21 02:07:05 ipfire unbound: [5113:0] info: service stopped (unbound 1.10.1).
Jun 21 02:07:05 ipfire unbound: [5113:0] info: server stats for thread 0: 10 queries, 1 answers from cache, 9 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jun 21 02:07:05 ipfire unbound: [5113:0] info: server stats for thread 0: requestlist max 1 avg 0.222222 exceeded 0 jostled 0
Jun 21 02:07:05 ipfire unbound: [5113:0] info: average recursion processing time 0.148931 sec
Jun 21 02:07:05 ipfire unbound: [5113:0] info: histogram of recursion processing times
Jun 21 02:07:05 ipfire unbound: [5113:0] info: [25%]=0.04096 median[50%]=0.090112 [75%]=0.126976
Jun 21 02:07:05 ipfire unbound: [5113:0] info: lower(secs) upper(secs) recursions
Jun 21 02:07:05 ipfire unbound: [5113:0] info:    0.016384    0.032768 2
Jun 21 02:07:05 ipfire unbound: [5113:0] info:    0.032768    0.065536 1
Jun 21 02:07:05 ipfire unbound: [5113:0] info:    0.065536    0.131072 4
Jun 21 02:07:05 ipfire unbound: [5113:0] info:    0.262144    0.524288 2
Jun 21 02:07:07 ipfire acpid: exiting
Jun 21 02:07:08 ipfire kernel: Kernel logging (proc) stopped.
Jun 21 02:07:08 ipfire kernel: Kernel log daemon terminating.
Jun 21 02:07:09 ipfire exiting on signal 15
------------------------------
Jun 21 02:15:31 ipfire syslogd 1.5.1: restart (remote reception).
Jun 21 02:15:31 ipfire unbound: [1634:0] notice: init module 0: validator
Jun 21 02:15:31 ipfire unbound: [1634:0] notice: init module 1: iterator
Jun 21 02:15:31 ipfire unbound: [1634:0] info: start of service (unbound 1.10.1).
Jun 21 02:15:31 ipfire acpid: starting up with netlink and the input layer
Jun 21 02:15:31 ipfire acpid: 1 rule loaded
Jun 21 02:15:31 ipfire acpid: waiting for events: event logging is off
Jun 21 02:15:32 ipfire dhcpcd[1795]: dhcpcd-9.0.2 starting
Jun 21 02:15:32 ipfire kernel: 8021q: 802.1Q VLAN Support v1.8
Jun 21 02:15:32 ipfire dhcpcd[1818]: DUID 00:01:00:01:26:81:63:24:xx:xx:xx....
Jun 21 02:15:32 ipfire dhcpcd[1818]: red0: IAID 5d:xx:......
Jun 21 02:15:32 ipfire dhcpcd[1818]: red0: adding address fe80::xxx
Jun 21 02:15:32 ipfire dhcpcd[1818]: ipv6_addaddr1: Permission denied
Jun 21 02:15:32 ipfire unbound: [1634:0] error: SERVFAIL <ns11.whois.co.kr. A IN>: all the configured stub or forward servers failed, at zone .
Jun 21 02:15:33 ipfire dhcpcd[1818]: red0: soliciting a DHCP lease
Jun 21 02:15:33 ipfire dhcpcd[1818]: red0: offered xxx.xxx.xxx.xxx from 10.34.113.1
Jun 21 02:15:33 ipfire dhcpcd[1818]: red0: probing address xxx.xxx.xxx.xxx/24
Jun 21 02:15:33 ipfire dhcpcd[1818]: red0: soliciting an IPv6 router
Jun 21 02:15:37 ipfire dhcpcd[1818]: red0: leased xxx.xxx.xxx.xxx for 3600 seconds
Jun 21 02:15:37 ipfire dhcpcd[1818]: red0: adding route to xxx.xxx.xxx.0/24
Jun 21 02:15:37 ipfire dhcpcd[1818]: red0: adding default route via xxx.xxx.xxx.1
Jun 21 02:15:38 ipfire dhcpcd.exe[1851]: red0 has been (re)configured with IP=xxx.xxx.xxx.xxx
Jun 21 02:15:38 ipfire unbound: [1634:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
Jun 21 02:15:38 ipfire unbound: [1634:0] info: service stopped (unbound 1.10.1).
Jun 21 02:15:38 ipfire unbound: [1634:0] info: server stats for thread 0: 2 queries, 0 answers from cache, 2 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Jun 21 02:15:38 ipfire unbound: [1634:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Jun 21 02:15:38 ipfire unbound: [1634:0] info: average recursion processing time 0.036877 sec
Jun 21 02:15:38 ipfire unbound: [1634:0] info: histogram of recursion processing times
Jun 21 02:15:38 ipfire unbound: [1634:0] info: [25%]=0 median[50%]=0 [75%]=0
Jun 21 02:15:38 ipfire unbound: [1634:0] info: lower(secs) upper(secs) recursions
Jun 21 02:15:38 ipfire unbound: [1634:0] info:    0.000000    0.000001 1
Jun 21 02:15:38 ipfire unbound: [1634:0] info:    0.065536    0.131072 1
Jun 21 02:15:38 ipfire unbound: [1634:0] notice: Restart of unbound 1.10.1.
Jun 21 02:15:38 ipfire unbound: [1634:0] notice: init module 0: validator
Jun 21 02:15:38 ipfire unbound: [1634:0] notice: init module 1: iterator
Jun 21 02:15:38 ipfire unbound: [1634:0] info: start of service (unbound 1.10.1).
Jun 21 02:15:38 ipfire unbound: [1634:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
Jun 21 02:15:45 ipfire kernel: tun: Universal TUN/TAP device driver, 1.6
Jun 21 02:15:45 ipfire openvpnserver[2314]: OpenVPN 2.4.9 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Jun  4 2020
Jun 21 02:15:45 ipfire openvpnserver[2314]: library versions: OpenSSL 1.1.1g  21 Apr 2020, LZO 2.09
Jun 21 02:15:45 ipfire openvpnserver[2315]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Jun 21 02:15:45 ipfire openvpnserver[2315]: Diffie-Hellman initialized with 2048 bit key
Jun 21 02:15:45 ipfire openvpnserver[2315]: CRL: loaded 1 CRLs from file /var/ipfire/ovpn/crls/cacrl.pem
Jun 21 02:15:45 ipfire openvpnserver[2315]: Outgoing Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Jun 21 02:15:45 ipfire openvpnserver[2315]: Incoming Control Channel Authentication: Using 256 bit message hash 'SHA256' for HMAC authentication
Jun 21 02:15:45 ipfire openvpnserver[2315]: ROUTE_GATEWAY xxx.xxx.xxx.1/255.255.255.0 IFACE=red0 HWADDR=00:xx:.....
Jun 21 02:15:45 ipfire openvpnserver[2315]: TUN/TAP device tun0 opened
Jun 21 02:15:45 ipfire openvpnserver[2315]: TUN/TAP TX queue length set to 100
Jun 21 02:15:45 ipfire openvpnserver[2315]: /sbin/ip link set dev tun0 up mtu 1500
Jun 21 02:15:45 ipfire openvpnserver[2315]: /sbin/ip addr add dev tun0 local 10.46.18.1 peer 10.46.18.2
Jun 21 02:15:45 ipfire openvpnserver[2315]: /sbin/ip route add 10.46.19.0/24 via 10.46.18.2
Jun 21 02:15:45 ipfire openvpnserver[2315]: /sbin/ip route add 10.46.18.0/24 via 10.46.18.2
Jun 21 02:15:45 ipfire openvpnserver[2315]: Could not determine IPv4/IPv6 protocol. Using AF_INET
Jun 21 02:15:45 ipfire openvpnserver[2315]: Socket Buffers: R=[212992->212992] S=[212992->212992]
Jun 21 02:15:45 ipfire openvpnserver[2315]: UDPv4 link local (bound): [AF_INET][undef]:1149
Jun 21 02:15:45 ipfire openvpnserver[2315]: UDPv4 link remote: [AF_UNSPEC]
Jun 21 02:15:45 ipfire openvpnserver[2315]: GID set to nobody
Jun 21 02:15:45 ipfire openvpnserver[2315]: UID set to nobody
Jun 21 02:15:45 ipfire openvpnserver[2315]: MULTI: multi_init called, r=256 v=256
Jun 21 02:15:45 ipfire openvpnserver[2315]: IFCONFIG POOL: base=10.46.18.4 size=62, ipv6=0
Jun 21 02:15:45 ipfire openvpnserver[2315]: IFCONFIG POOL LIST
Jun 21 02:15:45 ipfire openvpnserver[2315]: Initialization Sequence Completed
Jun 21 02:15:45 ipfire root: Could not find a bridged zone for tun0
Jun 21 02:15:45 ipfire vnstatd[1583]: Interface "tun0" enabled.
Jun 21 02:15:45 ipfire codel: Codel AQM has been enabled on 'tun0'.

Has anyone had the same problem or can reproduce it?
Thanks in advance

Sincerely
Thomas

Hi,

which Core Update are you running? Do you happen to have a Intel NIC using the e1000e driver in place?

Thanks, and best regards,
Peter Müller

Hi Peter,

I tried it with the latest 2.25 core update 145.
I also did a new installation without importing the backup from the old system, so the N2N OpenVPN isn’t the issue. The problem occurs on the first boot after the installation.

Funny thing is, that I have the exact same version of IPFire running on the same host except it’s x86.

IPFire is virtualized, the NICs on the guest are Hyper-V virtual adapters, on the host I use the onboard NICs (Supermicro)

Best regards
Thomas

I further investigated the problem. There is an issue with the
detection of MS Azure. I bypassed the function running_on_azure() in the init script /etc/rc.d/init.d/functions by letting it always return 1, which means that we are not running on azure. This fixed the problem. So I think that the helper/azure-setup script takes 8 minutes to terminate.

Btw. you can abort the script during boot with ^C
Host OS: Windows Server 2016 Standard 1607

https://community.ipfire.org/t/installing-ipfire-into-local-hyper-v-unknown-credentials/899

I’m currently short of time but I’ll try to also debug the azure-setup script.

Best regards
Thomas

Hi,

could you please open a bug at https://bugzilla.ipfire.org/ (your login credentials work there as well) for this and/or submit patches to the development mailing list? We would love to have your fixes in IPFire… :slight_smile:

Please refer to https://wiki.ipfire.org/devel/ for further information on IPFire development in general.

Thanks, and best regards,
Peter Müller

https://bugzilla.ipfire.org/show_bug.cgi?id=12445

I’ll try to get my hands on a trial verision of MS Azure. Maybe there is a way to distinguish between Azure and Hyper-V

Regards
Tom

1 Like

Thanks! :slight_smile:

Is there any update on the status of bug 12445? It seemed to me that the other solution to this is to change the order or initializing the Package Manager, by waiting until IPFire actually had all of its network interfaces defined and initialized. I have the same issue and am running 152 still and was wondering if the timeout “fix” was included in 153 or 154. If not, Peter, could you comment on the thoughts of moving the Package Manager startup to a point after the NICs are active? Azure or Hyper-V, the package manager would get an IP address properly if they were defined when it was starting.