OpenVPN2.4.6の起動方法について

[takahiro suzuki]

はじめまして、鈴木と申します。

CentOS7.1環境において、

お恥ずかしながらOpenVPNを起動できず困ってます。

環境とログを記載しますので切り分け手順についてご教示をお願いしたく。

環境は以下となります。

OS：CentOS7.1

　SDELINUXはオフにしてあります。

OpenVPN：2.4.6

osのsyslog（/var/log/messages）は以下です。

Jun 11 14:42:31 140-227-39-61 systemd: Starting OpenVPN Robust And Highly Flexible Tunneling Application On server...
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 Warning: Error redirecting stdout/stderr to --log file: /var/log/openvpn.log: Permission denied (errno=13)
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 OpenVPN 2.4.6 x86_64-redhat-linux-gnu [Fedora EPEL patched] [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Apr 26 2018
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 library versions: OpenSSL 1.0.2k-fips  26 Jan 2017, LZO 2.06
Jun 11 14:42:31 140-227-39-61 systemd: Started OpenVPN Robust And Highly Flexible Tunneling Application On server.
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 Diffie-Hellman initialized with 2048 bit key
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1278)
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 ROUTE_GATEWAY 140.227.39.1/255.255.255.0 IFACE=eth0 HWADDR=00:13:5d:11:10:ab
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 TUN/TAP device tun1 opened
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 TUN/TAP TX queue length set to 100
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 /sbin/ip link set dev tun1 up mtu 1278
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 /sbin/ip addr add dev tun1 local 172.31.0.1 peer 172.31.0.2
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): link connected
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): carrier is ON
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): new Tun device (driver: 'unknown' ifindex: 293)
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 /sbin/ip route add 172.31.0.0/16 via 172.31.0.2
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): exported as /org/freedesktop/NetworkManager/Devices/292
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): device state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 Could not determine IPv4/IPv6 protocol. Using AF_INET
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 Socket Buffers: R=[212992->212992] S=[212992->212992]
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 TCP/UDP: Socket bind failed on local address [AF_INET][undef]:1194: Address already in use (errno=98)
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 Exiting due to fatal error
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 /sbin/ip route del 172.31.0.0/16
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): device state change: unavailable -> disconnected (reason 'connection-assumed') [20 30 41]
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: starting connection 'tun1'
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: Stage 1 of 5 (Device Prepare) scheduled...
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: Stage 1 of 5 (Device Prepare) started...
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: Stage 2 of 5 (Device Configure) scheduled...
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 Closing TUN/TAP interface
Jun 11 14:42:31 140-227-39-61 openvpn: Mon Jun 11 14:42:31 2018 /sbin/ip addr del dev tun1 local 172.31.0.1 peer 172.31.0.2
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: Stage 1 of 5 (Device Prepare) complete.
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: Stage 2 of 5 (Device Configure) starting...
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): device state change: prepare -> config (reason 'none') [40 50 0]
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: Stage 2 of 5 (Device Configure) successful.
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: Stage 3 of 5 (IP Configure Start) scheduled.
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: Stage 2 of 5 (Device Configure) complete.
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: Stage 3 of 5 (IP Configure Start) started...
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): device state change: config -> ip-config (reason 'none') [50 70 0]
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <error> [1528695751.698958] [platform/nm-linux-platform.c:2352] link_change(): Netlink error changing link 293:  <DOWN> mtu 0 (1) driver 'unknown' udi '/sys/devices/virtual/net/tun1': Address family not supported
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <warn>  (tun1): failed to disable userspace IPv6LL address handling
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): Activation: Stage 3 of 5 (IP Configure Start) complete.
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): device state change: ip-config -> unmanaged (reason 'removed') [70 10 36]
Jun 11 14:42:31 140-227-39-61 NetworkManager[715]: <info>  (tun1): deactivating device (reason 'removed') [36]
Jun 11 14:42:31 140-227-39-61 systemd: ope...@server.service: main process exited, code=exited, status=1/FAILURE
Jun 11 14:42:31 140-227-39-61 systemd: Unit ope...@server.service entered failed state.
Jun 11 14:42:31 140-227-39-61 systemd: ope...@server.service failed.

opevpn.log配下になります。

Mon Jun 11 13:16:08 2018 OpenVPN 2.4.6 x86_64-redhat-linux-gnu [Fedora EPEL patched] [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] built on Apr 26 2018
Mon Jun 11 13:16:08 2018 library versions: OpenSSL 1.0.2k-fips  26 Jan 2017, LZO 2.06
Mon Jun 11 13:16:08 2018 Diffie-Hellman initialized with 2048 bit key
Mon Jun 11 13:16:08 2018 WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1278)
Mon Jun 11 13:16:08 2018 ROUTE_GATEWAY 140.227.39.1/255.255.255.0 IFACE=eth0 HWADDR=00:13:5d:11:10:ab
Mon Jun 11 13:16:08 2018 TUN/TAP device tun1 opened
Mon Jun 11 13:16:08 2018 TUN/TAP TX queue length set to 100
Mon Jun 11 13:16:08 2018 do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Mon Jun 11 13:16:08 2018 /sbin/ip link set dev tun1 up mtu 1278
Mon Jun 11 13:16:08 2018 /sbin/ip addr add dev tun1 local 172.31.0.1 peer 172.31.0.2
Mon Jun 11 13:16:08 2018 /sbin/ip route add 172.31.0.0/16 via 172.31.0.2
Mon Jun 11 13:16:08 2018 Could not determine IPv4/IPv6 protocol. Using AF_INET
Mon Jun 11 13:16:08 2018 Socket Buffers: R=[212992->212992] S=[212992->212992]
Mon Jun 11 13:16:08 2018 TCP/UDP: Socket bind failed on local address [AF_INET][undef]:1194: Address already in use (errno=98)
Mon Jun 11 13:16:08 2018 Exiting due to fatal error
Mon Jun 11 13:16:08 2018 /sbin/ip route del 172.31.0.0/16
Mon Jun 11 13:16:08 2018 Closing TUN/TAP interface
Mon Jun 11 13:16:08 2018 /sbin/ip addr del dev tun1 local 172.31.0.1 peer 172.31.0.2

[takahiro suzuki]

2018年6月11日月曜日 15時05分39秒 UTC+9 takahiro suzuki:

[Taro Yamazaki]

鈴木さま

はじめまして、やまざきと申します。

ログから拝見するに、

> Mon Jun 11 13:16:08 2018 TCP/UDP: Socket bind failed on local address [AF_INET][undef]:1194: Address already in use (errno=98)
> Mon Jun 11 13:16:08 2018 Exiting due to fatal error

とのことですので、OpenVPNで使用するポート 1194が他のプロセスによって使用されていることが原因のように見受けられます。
別のOpenVPNインスタンスの可能性もありますので、netstatコマンドなどで使用プロセスをご確認ください。

よろしくお願いいたします。

> --
> このメールは Google グループのグループ「OpenVPN Japan Users Group」に登録しているユーザーに送られています。
> このグループから退会し、グループからのメールの配信を停止するには openvpn-japan-user...@googlegroups.com <mailto:openvpn-japan-user...@googlegroups.com> にメールを送信してください。
> その他のオプションについては https://groups.google.com/d/optout にアクセスしてください。

--
::: Taro Yamazaki [ ta...@plum-systems.co.jp ]
: <Blog> http://yamatamemo.blogspot.jp/
: <LinkedIn> http://www.linkedin.com/in/yamata
-------------------------------------------------------------
: Plum Systems Inc.
: 2-3-11-2F, Kurihira, Asao-ku,
: Kawasaki, Kanagawa
: http://www.plum-systems.co.jp/

[takahiro suzuki]

やまざきさま

鈴木です、お世話になります。

お返事ありがとうございます。

おっしゃる通り# ssコマンドにて確認したところ、

何らかゾンビプロセスによりudp1194ポートがリスニングしてましたので

killし、 #　systemctl により起動した所、正常起動しました。

私自身サーバ設計構築から大分長い間遠ざかっていたために、

CentOSのアーキテクチャがinit→systemdに変わったことを把握せずに、

臨んだために大分混乱もあって、手動でプロセスを上げようとしたり、

systemdで起動しようとしたりしたものが混在させたり等したことが原因でした。

無事、構築も進みました。貴重なご回答ありがとうございました。

> このグループから退会し、グループからのメールの配信を停止するには openvpn-japan-users-group+unsub...@googlegroups.com <mailto:openvpn-japan-users-group+unsubscribe@googlegroups.com> にメールを送信してください。

> その他のオプションについては https://groups.google.com/d/optout にアクセスしてください。

--
::: Taro Yamazaki [ ta...@plum-systems.co.jp ]
:    <Blog> http://yamatamemo.blogspot.jp/
:    <LinkedIn> http://www.linkedin.com/in/yamata
-------------------------------------------------------------
: Plum Systems Inc.
: 2-3-11-2F, Kurihira, Asao-ku,
: Kawasaki, Kanagawa
: http://www.plum-systems.co.jp/

--
このメールは Google グループのグループ「OpenVPN Japan Users Group」の登録者に送られています。

このグループから退会し、グループからのメールの配信を停止するには openvpn-japan-users-group+unsub...@googlegroups.com にメールを送信してください。
その他のオプションについては、https://groups.google.com/d/optout にアクセスしてください。