Timeout error during startup

sulaimankhan

i'm getting a timeout error when I try to start up the openvpn service. I'm running v2.5.3

[root@vpn-dev-0830 server]# systemctl start openvpn-server@server
Job for openvpn-server@server.service failed because a timeout was exceeded. See "systemctl status openvpn-server@server.service" and "journalctl -xe" for details.

The logs aren't giving me much information, it looks like it's getting stuck while nm-dispatcher is running some scripts. I set the log verbosity to 10 and got this... Any idea what could be causing this?

Aug 31 06:10:56 vpn-dev-0830 NetworkManager[1082]: <info> [1630390256.0165] device (tun0): Activation: successful, device activated.
Aug 31 06:10:56 vpn-dev-0830 nm-dispatcher: req:2 'up' [tun0]: new request (3 scripts)
Aug 31 06:10:56 vpn-dev-0830 nm-dispatcher: req:2 'up' [tun0]: start running ordered scripts...
Aug 31 06:11:00 vpn-dev-0830 openvpn: EP_WAIT[0] rwflags=0x0001 ev=0x00000001 arg=0x00000002
Aug 31 06:11:00 vpn-dev-0830 openvpn: MULTI: REAP range 0 -> 16
Aug 31 06:11:00 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_action a=TA_TUN_READ p=0
Aug 31 06:11:00 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TUN_READ mi=0x00000000
Aug 31 06:11:00 vpn-dev-0830 openvpn: read from TUN/TAP returned 48
Aug 31 06:11:00 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_post TA_TUN_READ -> TA_UNDEF
Aug 31 06:11:00 vpn-dev-0830 openvpn: SCHEDULE: schedule_find_least NULL
Aug 31 06:11:04 vpn-dev-0830 openvpn: EP_WAIT[0] rwflags=0x0001 ev=0x00000001 arg=0x00000002
Aug 31 06:11:04 vpn-dev-0830 openvpn: MULTI: REAP range 16 -> 32
Aug 31 06:11:04 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_action a=TA_TUN_READ p=0
Aug 31 06:11:04 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TUN_READ mi=0x00000000
Aug 31 06:11:04 vpn-dev-0830 openvpn: read from TUN/TAP returned 48
Aug 31 06:11:04 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_post TA_TUN_READ -> TA_UNDEF
Aug 31 06:11:04 vpn-dev-0830 openvpn: SCHEDULE: schedule_find_least NULL
Aug 31 06:11:14 vpn-dev-0830 openvpn: MULTI: REAP range 32 -> 48
Aug 31 06:11:14 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Aug 31 06:11:14 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Aug 31 06:11:14 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Aug 31 06:11:14 vpn-dev-0830 openvpn: SCHEDULE: schedule_find_least NULL
Aug 31 06:11:24 vpn-dev-0830 openvpn: MULTI: REAP range 48 -> 64
Aug 31 06:11:24 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Aug 31 06:11:24 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Aug 31 06:11:24 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Aug 31 06:11:24 vpn-dev-0830 openvpn: SCHEDULE: schedule_find_least NULL
Aug 31 06:11:34 vpn-dev-0830 openvpn: MULTI: REAP range 64 -> 80
Aug 31 06:11:34 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Aug 31 06:11:34 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Aug 31 06:11:34 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Aug 31 06:11:34 vpn-dev-0830 openvpn: SCHEDULE: schedule_find_least NULL
Aug 31 06:11:44 vpn-dev-0830 openvpn: MULTI: REAP range 80 -> 96
Aug 31 06:11:44 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Aug 31 06:11:44 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Aug 31 06:11:44 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Aug 31 06:11:44 vpn-dev-0830 openvpn: SCHEDULE: schedule_find_least NULL
Aug 31 06:11:54 vpn-dev-0830 openvpn: MULTI: REAP range 96 -> 112
Aug 31 06:11:54 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Aug 31 06:11:54 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Aug 31 06:11:54 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Aug 31 06:11:54 vpn-dev-0830 openvpn: SCHEDULE: schedule_find_least NULL
Aug 31 06:12:04 vpn-dev-0830 openvpn: MULTI: REAP range 112 -> 128
Aug 31 06:12:04 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Aug 31 06:12:04 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Aug 31 06:12:04 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Aug 31 06:12:04 vpn-dev-0830 openvpn: SCHEDULE: schedule_find_least NULL
Aug 31 06:12:14 vpn-dev-0830 openvpn: MULTI: REAP range 128 -> 144
Aug 31 06:12:14 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Aug 31 06:12:14 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Aug 31 06:12:14 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Aug 31 06:12:14 vpn-dev-0830 openvpn: SCHEDULE: schedule_find_least NULL
Aug 31 06:12:24 vpn-dev-0830 openvpn: MULTI: REAP range 144 -> 160
Aug 31 06:12:24 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Aug 31 06:12:24 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Aug 31 06:12:24 vpn-dev-0830 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Aug 31 06:12:24 vpn-dev-0830 openvpn: SCHEDULE: schedule_find_least NULL
Aug 31 06:12:26 vpn-dev-0830 systemd: openvpn-server@server.service start operation timed out. Terminating.
Aug 31 06:12:26 vpn-dev-0830 openvpn: MULTI: REAP range 0 -> 256
Aug 31 06:12:26 vpn-dev-0830 openvpn: TCP/UDP: Closing socket
Aug 31 06:12:26 vpn-dev-0830 openvpn: Closing TUN/TAP interface
Aug 31 06:12:26 vpn-dev-0830 openvpn: net_addr_v4_del: 10.8.0.1 dev tun0
Aug 31 06:12:26 vpn-dev-0830 openvpn: sitnl_send: checking for received messages
Aug 31 06:12:26 vpn-dev-0830 openvpn: sitnl_send: rtnl: received 52 bytes
Aug 31 06:12:26 vpn-dev-0830 openvpn: sitnl_send: rtnl: generic error (-1): Operation not permitted
Aug 31 06:12:26 vpn-dev-0830 openvpn: Linux can't del IP from iface tun0

server.conf

port 443
proto tcp
dev tun
topology subnet
ca ca.crt
cert serverkey.crt
key serverkey.key
dh dh.pem
server 10.8.0.0 255.255.255.0
ifconfig-pool-persist ipp.txt
keepalive 10 120
tls-auth tiv.key 0 # This file is secret
key-direction 0
cipher AES-256-GCM
comp-lzo
user nobody
group nobody
persist-key
persist-tun
status openvpn-status.log
verb 10

300000

vpn-dev-0830 openvpn: sitnl_send: rtnl: generic error (-1): Operation not permitted

You need run with root permission or it cant start

sulaimankhan

300000 wrote vpn-dev-0830 openvpn: sitnl_send: rtnl: generic error (-1): Operation not permitted

You need run with root permission or it cant start

I am starting the service as root, the logs are showing the operation timing out before it even gets to the "operation not permitted"

TinCanTech

sulaimankhan wrote I am starting the service as root

Evidence ?

https://forums.openvpn.net/viewtopic.php?f=30&t=22603

sulaimankhan

TinCanTech wrote

Evidence ?

https://forums.openvpn.net/viewtopic.php?f=30&t=22603
[/quote]

Apologies, I assumed i was running as root. I updated the user to run as root and the "Operation not permitted" error is gone but it is still timing out [Line 58]. The service times out and then attempts to restart. This goes on in a loop until I stop the service. Logs below

ep 1 20:22:03 openvpn-custom-0901 NetworkManager[514]: <info> [1630527723.1488] device (tun0): Activation: successful, device activated.
Sep 1 20:22:03 openvpn-custom-0901 nm-dispatcher: req:2 'up' [tun0]: new request (3 scripts)
Sep 1 20:22:03 openvpn-custom-0901 nm-dispatcher: req:2 'up' [tun0]: start running ordered scripts...
Sep 1 20:22:07 openvpn-custom-0901 openvpn: EP_WAIT[0] rwflags=0x0001 ev=0x00000001 arg=0x00000002
Sep 1 20:22:07 openvpn-custom-0901 openvpn: MULTI: REAP range 0 -> 16
Sep 1 20:22:07 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_action a=TA_TUN_READ p=0
Sep 1 20:22:07 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TUN_READ mi=0x00000000
Sep 1 20:22:07 openvpn-custom-0901 openvpn: read from TUN/TAP returned 48
Sep 1 20:22:07 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_post TA_TUN_READ -> TA_UNDEF
Sep 1 20:22:07 openvpn-custom-0901 openvpn: SCHEDULE: schedule_find_least NULL
Sep 1 20:22:11 openvpn-custom-0901 openvpn: EP_WAIT[0] rwflags=0x0001 ev=0x00000001 arg=0x00000002
Sep 1 20:22:11 openvpn-custom-0901 openvpn: MULTI: REAP range 16 -> 32
Sep 1 20:22:11 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_action a=TA_TUN_READ p=0
Sep 1 20:22:11 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TUN_READ mi=0x00000000
Sep 1 20:22:11 openvpn-custom-0901 openvpn: read from TUN/TAP returned 48
Sep 1 20:22:11 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_post TA_TUN_READ -> TA_UNDEF
Sep 1 20:22:11 openvpn-custom-0901 openvpn: SCHEDULE: schedule_find_least NULL
Sep 1 20:22:21 openvpn-custom-0901 openvpn: MULTI: REAP range 32 -> 48
Sep 1 20:22:21 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Sep 1 20:22:21 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Sep 1 20:22:21 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Sep 1 20:22:21 openvpn-custom-0901 openvpn: SCHEDULE: schedule_find_least NULL
Sep 1 20:22:31 openvpn-custom-0901 openvpn: MULTI: REAP range 48 -> 64
Sep 1 20:22:31 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Sep 1 20:22:31 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Sep 1 20:22:31 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Sep 1 20:22:31 openvpn-custom-0901 openvpn: SCHEDULE: schedule_find_least NULL
Sep 1 20:22:41 openvpn-custom-0901 openvpn: MULTI: REAP range 64 -> 80
Sep 1 20:22:41 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Sep 1 20:22:41 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Sep 1 20:22:41 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Sep 1 20:22:41 openvpn-custom-0901 openvpn: SCHEDULE: schedule_find_least NULL
Sep 1 20:22:51 openvpn-custom-0901 openvpn: MULTI: REAP range 80 -> 96
Sep 1 20:22:51 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Sep 1 20:22:51 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Sep 1 20:22:51 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Sep 1 20:22:51 openvpn-custom-0901 openvpn: SCHEDULE: schedule_find_least NULL
Sep 1 20:23:01 openvpn-custom-0901 openvpn: MULTI: REAP range 96 -> 112
Sep 1 20:23:01 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Sep 1 20:23:01 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Sep 1 20:23:01 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Sep 1 20:23:01 openvpn-custom-0901 openvpn: SCHEDULE: schedule_find_least NULL
Sep 1 20:23:11 openvpn-custom-0901 openvpn: MULTI: REAP range 112 -> 128
Sep 1 20:23:11 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Sep 1 20:23:11 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Sep 1 20:23:11 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Sep 1 20:23:11 openvpn-custom-0901 openvpn: SCHEDULE: schedule_find_least NULL
Sep 1 20:23:21 openvpn-custom-0901 openvpn: MULTI: REAP range 128 -> 144
Sep 1 20:23:21 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Sep 1 20:23:21 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Sep 1 20:23:21 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Sep 1 20:23:21 openvpn-custom-0901 openvpn: SCHEDULE: schedule_find_least NULL
Sep 1 20:23:31 openvpn-custom-0901 openvpn: MULTI: REAP range 144 -> 160
Sep 1 20:23:31 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0
Sep 1 20:23:31 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000
Sep 1 20:23:31 openvpn-custom-0901 openvpn: MULTI TCP: multi_tcp_post TA_TIMEOUT -> TA_UNDEF
Sep 1 20:23:31 openvpn-custom-0901 openvpn: SCHEDULE: schedule_find_least NULL
Sep 1 20:23:33 openvpn-custom-0901 systemd: openvpn-server@server.service start operation timed out. Terminating.
Sep 1 20:23:33 openvpn-custom-0901 openvpn: MULTI: REAP range 0 -> 256
Sep 1 20:23:33 openvpn-custom-0901 openvpn: TCP/UDP: Closing socket
Sep 1 20:23:33 openvpn-custom-0901 openvpn: net_route_v4_del: 10.8.0.0/24 via 10.8.0.2 dev [NULL] table 0 metric -1
Sep 1 20:23:33 openvpn-custom-0901 openvpn: sitnl_send: checking for received messages
Sep 1 20:23:33 openvpn-custom-0901 openvpn: sitnl_send: rtnl: received 36 bytes
Sep 1 20:23:33 openvpn-custom-0901 openvpn: Closing TUN/TAP interface
Sep 1 20:23:33 openvpn-custom-0901 openvpn: net_addr_ptp_v4_del: 10.8.0.1 dev tun0
Sep 1 20:23:33 openvpn-custom-0901 openvpn: sitnl_send: checking for received messages
Sep 1 20:23:33 openvpn-custom-0901 openvpn: sitnl_send: rtnl: received 36 bytes
Sep 1 20:23:33 openvpn-custom-0901 NetworkManager[514]: <info> [1630527813.3603] device (tun0): state change: activated -> unmanaged (reason 'unmanaged', sys-iface-state: 'removed')
Sep 1 20:23:33 openvpn-custom-0901 openvpn: PID packet_id_free
Sep 1 20:23:33 openvpn-custom-0901 openvpn: SIGTERM[hard,] received, process exiting
Sep 1 20:23:33 openvpn-custom-0901 dbus[458]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service'
Sep 1 20:23:33 openvpn-custom-0901 systemd: Starting Network Manager Script Dispatcher Service...
Sep 1 20:23:33 openvpn-custom-0901 systemd: Failed to start OpenVPN service for server.
Sep 1 20:23:33 openvpn-custom-0901 systemd: Unit openvpn-server@server.service entered failed state.
Sep 1 20:23:33 openvpn-custom-0901 systemd: openvpn-server@server.service failed.
Sep 1 20:23:33 openvpn-custom-0901 dbus[458]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Sep 1 20:23:33 openvpn-custom-0901 nm-dispatcher: req:1 'down' [tun0]: new request (3 scripts)
Sep 1 20:23:33 openvpn-custom-0901 systemd: Started Network Manager Script Dispatcher Service.
Sep 1 20:23:33 openvpn-custom-0901 nm-dispatcher: req:1 'down' [tun0]: start running ordered scripts...
Sep 1 20:23:38 openvpn-custom-0901 systemd: openvpn-server@server.service holdoff time over, scheduling restart.
Sep 1 20:23:38 openvpn-custom-0901 systemd: Stopped OpenVPN service for server.
Sep 1 20:23:38 openvpn-custom-0901 systemd: Starting OpenVPN service for server...

300000

This is not a normal log on openvpn but from other script so maybe that script not working correctly. in the log non of other info show in here so try to correct yourself a program to call openvpn first. nothing to do with openvpn at all .

TinCanTech

sulaimankhan wrote Line 58:

Sep 1 20:23:33 openvpn-custom-0901 systemd: openvpn-server@server.service start operation timed out. Terminating.

You need your Openvpn log file.

See --log in the manual.