Project

General

Profile

Bug #7905 » openvpn-auth-script-test.log

Full server process log - partially redacted (UTC) - Phil DeMonaco, 02/23/2018 04:05 PM

 
1
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: MANAGEMENT: unix domain socket listening on /var/etc/openvpn/server2.sock
2
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
3
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: PLUGIN_INIT: POST /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so '[/usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so] [/usr/local/sbin/ovpn_auth_verify_async] [user] [YmYwX2R1bzAw] [false] [server2] [1195]' intercepted=PLUGIN_AUTH_USER_PASS_VERIFY 
4
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: Diffie-Hellman initialized with 2048 bit key
5
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: TLS-Auth MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
6
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: TUN/TAP device ovpns2 exists previously, keep at program end
7
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: TUN/TAP device /dev/tun2 opened
8
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
9
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: /sbin/ifconfig ovpns2 172.29.128.1 172.29.128.2 mtu 1500 netmask 255.255.255.128 up
10
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: /sbin/route add -net 172.29.128.0 172.29.128.2 255.255.255.128
11
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: /usr/local/sbin/ovpn-linkup ovpns2 1500 1621 172.29.128.1 255.255.255.128 init
12
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
13
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: Socket Buffers: R=[42080->42080] S=[57344->57344]
14
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: UDPv4 link local (bound): [AF_INET]40.142.36.20:1195
15
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: UDPv4 link remote: [AF_UNSPEC]
16
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: MULTI: multi_init called, r=256 v=256
17
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: IFCONFIG POOL: base=172.29.128.2 size=124, ipv6=0
18
Feb 23 21:01:58 d0-nfw2533 openvpn[29675]: Initialization Sequence Completed
19
Feb 23 21:02:03 d0-nfw2533 openvpn[29675]: MANAGEMENT: Client connected from /var/etc/openvpn/server2.sock
20
Feb 23 21:02:03 d0-nfw2533 openvpn[29675]: MANAGEMENT: CMD 'status 2'
21
Feb 23 21:02:03 d0-nfw2533 openvpn[29675]: MANAGEMENT: Client disconnected
22
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: MULTI: multi_create_instance called
23
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 Re-using SSL/TLS context
24
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
25
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
26
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
27
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
28
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [14] from [AF_INET]<client-ip>:46072: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
29
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 TLS: Initial packet from [AF_INET]<client-ip>:46072, sid=8885966c 8c782160
30
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [26] to [AF_INET]<client-ip>:46072: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
31
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [22] from [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 0 ]
32
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [187] from [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=1 DATA len=173
33
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [1200] to [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ 1 ] pid=1 DATA len=1174
34
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [1188] to [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=2 DATA len=1174
35
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [1188] to [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=3 DATA len=1174
36
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [510] to [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=496
37
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [22] from [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 1 ]
38
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [22] from [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 2 ]
39
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [22] from [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 3 ]
40
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [152] from [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ 4 ] pid=2 DATA len=126
41
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [77] to [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ 2 ] pid=5 DATA len=51
42
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [453] from [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ 5 ] pid=3 DATA len=427
43
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 peer info: IV_VER=2.4.4
44
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 peer info: IV_PLAT=freebsd
45
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 peer info: IV_PROTO=2
46
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 peer info: IV_NCP=2
47
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 peer info: IV_LZ4=1
48
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 peer info: IV_LZ4v2=1
49
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 peer info: IV_LZO=1
50
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 peer info: IV_COMP_STUB=1
51
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 peer info: IV_COMP_STUBv2=1
52
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 peer info: IV_TCPNL=1
53
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 PLUGIN_CALL: POST /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
54
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 TLS: Username/Password authentication deferred for username '<client-user>' [CN SET]
55
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [252] to [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ 3 ] pid=6 DATA len=226
56
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [22] from [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 6 ]
57
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384
58
Feb 23 21:02:31 d0-nfw2533 openvpn[29675]: <client-ip>:46072 [<client-user>] Peer Connection Initiated with [AF_INET]<client-ip>:46072
59
Feb 23 21:02:32 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [56] from [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=42
60
Feb 23 21:02:32 d0-nfw2533 openvpn[29675]: <client-ip>:46072 PUSH: Received control message: 'PUSH_REQUEST'
61
Feb 23 21:02:32 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [22] to [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 4 ]
62
Feb 23 21:02:37 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [56] from [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=5 DATA len=42
63
Feb 23 21:02:37 d0-nfw2533 openvpn[29675]: <client-ip>:46072 PUSH: Received control message: 'PUSH_REQUEST'
64
Feb 23 21:02:37 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [22] to [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 5 ]
65
Feb 23 21:02:42 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [56] from [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=6 DATA len=42
66
Feb 23 21:02:42 d0-nfw2533 openvpn[29675]: <client-ip>:46072 PUSH: Received control message: 'PUSH_REQUEST'
67
Feb 23 21:02:42 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [22] to [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 6 ]
68
Feb 23 21:02:47 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [56] from [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=42
69
Feb 23 21:02:47 d0-nfw2533 openvpn[29675]: <client-ip>:46072 PUSH: Received control message: 'PUSH_REQUEST'
70
Feb 23 21:02:47 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [22] to [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 7 ]
71
Feb 23 21:02:52 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [56] from [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=8 DATA len=42
72
Feb 23 21:02:52 d0-nfw2533 openvpn[29675]: <client-ip>:46072 PUSH: Received control message: 'PUSH_REQUEST'
73
Feb 23 21:02:52 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [22] to [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 8 ]
74
Feb 23 21:02:58 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [56] from [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=9 DATA len=42
75
Feb 23 21:02:58 d0-nfw2533 openvpn[29675]: <client-ip>:46072 PUSH: Received control message: 'PUSH_REQUEST'
76
Feb 23 21:02:58 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [22] to [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 9 ]
77
Feb 23 21:03:03 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 READ [56] from [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=10 DATA len=42
78
Feb 23 21:03:03 d0-nfw2533 openvpn[29675]: <client-ip>:46072 PUSH: Received control message: 'PUSH_REQUEST'
79
Feb 23 21:03:03 d0-nfw2533 openvpn[29675]: <client-ip>:46072 UDPv4 WRITE [22] to [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 10 ]
80
Feb 23 21:03:04 d0-nfw2533 openvpn[29675]: event_wait : Interrupted system call (code=4)
81
Feb 23 21:03:08 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:46072 MULTI_sva: pool returned IPv4=172.29.128.2, IPv6=(Not enabled)
82
Feb 23 21:03:08 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:46072 WARNING: Failed running command (--client-connect): external program fork failed
83
Feb 23 21:03:08 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:46072 UDPv4 READ [56] from [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=11 DATA len=42
84
Feb 23 21:03:08 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:46072 PUSH: Received control message: 'PUSH_REQUEST'
85
Feb 23 21:03:08 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:46072 Delayed exit in 5 seconds
86
Feb 23 21:03:08 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:46072 SENT CONTROL [<client-user>]: 'AUTH_FAILED' (status=1)
87
Feb 23 21:03:08 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:46072 UDPv4 WRITE [22] to [AF_INET]<client-ip>:46072: P_ACK_V1 kid=0 [ 11 ]
88
Feb 23 21:03:08 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:46072 UDPv4 WRITE [55] to [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=41
89
Feb 23 21:03:10 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:46072 UDPv4 WRITE [55] to [AF_INET]<client-ip>:46072: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=41
90
Feb 23 21:03:13 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:46072 SIGTERM[soft,delayed-exit] received, client-instance exiting
91
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: MULTI: multi_create_instance called
92
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Re-using SSL/TLS context
93
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
94
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
95
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
96
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
97
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [14] from [AF_INET]<client-ip>:43518: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
98
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 TLS: Initial packet from [AF_INET]<client-ip>:43518, sid=793910da ae628e12
99
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [26] to [AF_INET]<client-ip>:43518: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
100
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 0 ]
101
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [187] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=1 DATA len=173
102
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1200] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 1 ] pid=1 DATA len=1174
103
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1188] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=2 DATA len=1174
104
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1188] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=3 DATA len=1174
105
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [510] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=496
106
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 1 ]
107
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 2 ]
108
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 3 ]
109
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [152] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 4 ] pid=2 DATA len=126
110
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [77] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 2 ] pid=5 DATA len=51
111
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [453] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 5 ] pid=3 DATA len=427
112
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_VER=2.4.4
113
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_PLAT=freebsd
114
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_PROTO=2
115
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_NCP=2
116
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZ4=1
117
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZ4v2=1
118
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZO=1
119
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_COMP_STUB=1
120
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_COMP_STUBv2=1
121
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_TCPNL=1
122
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PLUGIN_CALL: POST /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
123
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 TLS: Username/Password authentication deferred for username '<client-user>' [CN SET]
124
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [252] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 3 ] pid=6 DATA len=226
125
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 6 ]
126
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384
127
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: <client-ip>:43518 [<client-user>] Peer Connection Initiated with [AF_INET]<client-ip>:43518
128
Feb 23 21:09:38 d0-nfw2533 openvpn[29675]: event_wait : Interrupted system call (code=4)
129
Feb 23 21:09:39 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=42
130
Feb 23 21:09:39 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
131
Feb 23 21:09:39 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Delayed exit in 5 seconds
132
Feb 23 21:09:39 d0-nfw2533 openvpn[29675]: <client-ip>:43518 SENT CONTROL [<client-user>]: 'AUTH_FAILED' (status=1)
133
Feb 23 21:09:39 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 4 ]
134
Feb 23 21:09:39 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [55] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=41
135
Feb 23 21:09:42 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [55] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=41
136
Feb 23 21:09:44 d0-nfw2533 openvpn[29675]: <client-ip>:43518 SIGTERM[soft,delayed-exit] received, client-instance exiting
137
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: MULTI: multi_create_instance called
138
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Re-using SSL/TLS context
139
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
140
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
141
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
142
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
143
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [14] from [AF_INET]<client-ip>:43518: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
144
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 TLS: Initial packet from [AF_INET]<client-ip>:43518, sid=516cb433 68ed6f92
145
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [26] to [AF_INET]<client-ip>:43518: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
146
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 0 ]
147
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [187] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=1 DATA len=173
148
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1200] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 1 ] pid=1 DATA len=1174
149
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1188] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=2 DATA len=1174
150
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1188] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=3 DATA len=1174
151
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [510] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=496
152
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 1 ]
153
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 2 ]
154
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 3 ]
155
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [152] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 4 ] pid=2 DATA len=126
156
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [77] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 2 ] pid=5 DATA len=51
157
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [454] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 5 ] pid=3 DATA len=428
158
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_VER=2.4.4
159
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_PLAT=freebsd
160
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_PROTO=2
161
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_NCP=2
162
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZ4=1
163
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZ4v2=1
164
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZO=1
165
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_COMP_STUB=1
166
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_COMP_STUBv2=1
167
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_TCPNL=1
168
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PLUGIN_CALL: POST /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
169
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 TLS: Username/Password authentication deferred for username '<client-user>' [CN SET]
170
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [252] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 3 ] pid=6 DATA len=226
171
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 6 ]
172
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384
173
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: <client-ip>:43518 [<client-user>] Peer Connection Initiated with [AF_INET]<client-ip>:43518
174
Feb 23 21:10:06 d0-nfw2533 openvpn[29675]: event_wait : Interrupted system call (code=4)
175
Feb 23 21:10:07 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=42
176
Feb 23 21:10:07 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
177
Feb 23 21:10:07 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Delayed exit in 5 seconds
178
Feb 23 21:10:07 d0-nfw2533 openvpn[29675]: <client-ip>:43518 SENT CONTROL [<client-user>]: 'AUTH_FAILED' (status=1)
179
Feb 23 21:10:07 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 4 ]
180
Feb 23 21:10:07 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [55] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=41
181
Feb 23 21:10:10 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [55] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=41
182
Feb 23 21:10:12 d0-nfw2533 openvpn[29675]: <client-ip>:43518 SIGTERM[soft,delayed-exit] received, client-instance exiting
183
Feb 23 21:10:14 d0-nfw2533 openvpn[29675]: MULTI: multi_create_instance called
184
Feb 23 21:10:14 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Re-using SSL/TLS context
185
Feb 23 21:10:14 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
186
Feb 23 21:10:14 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
187
Feb 23 21:10:14 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
188
Feb 23 21:10:14 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1557,tun-mtu 1500,proto UDPv4,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
189
Feb 23 21:10:14 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [14] from [AF_INET]<client-ip>:43518: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
190
Feb 23 21:10:14 d0-nfw2533 openvpn[29675]: <client-ip>:43518 TLS: Initial packet from [AF_INET]<client-ip>:43518, sid=47e7d642 44b4b369
191
Feb 23 21:10:14 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [26] to [AF_INET]<client-ip>:43518: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
192
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 0 ]
193
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [187] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=1 DATA len=173
194
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1200] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 1 ] pid=1 DATA len=1174
195
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1188] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=2 DATA len=1174
196
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1188] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=3 DATA len=1174
197
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [510] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=496
198
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 1 ]
199
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 2 ]
200
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 3 ]
201
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [152] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 4 ] pid=2 DATA len=126
202
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [77] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 2 ] pid=5 DATA len=51
203
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [453] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 5 ] pid=3 DATA len=427
204
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_VER=2.4.4
205
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_PLAT=freebsd
206
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_PROTO=2
207
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_NCP=2
208
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZ4=1
209
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZ4v2=1
210
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZO=1
211
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_COMP_STUB=1
212
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_COMP_STUBv2=1
213
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_TCPNL=1
214
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PLUGIN_CALL: POST /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
215
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 TLS: Username/Password authentication deferred for username '<client-user>' [CN SET]
216
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [252] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 3 ] pid=6 DATA len=226
217
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 6 ]
218
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384
219
Feb 23 21:10:15 d0-nfw2533 openvpn[29675]: <client-ip>:43518 [<client-user>] Peer Connection Initiated with [AF_INET]<client-ip>:43518
220
Feb 23 21:10:16 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=42
221
Feb 23 21:10:16 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
222
Feb 23 21:10:16 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 4 ]
223
Feb 23 21:10:21 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=5 DATA len=42
224
Feb 23 21:10:21 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
225
Feb 23 21:10:21 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 5 ]
226
Feb 23 21:10:26 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=6 DATA len=42
227
Feb 23 21:10:26 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
228
Feb 23 21:10:26 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 6 ]
229
Feb 23 21:10:31 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=42
230
Feb 23 21:10:31 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
231
Feb 23 21:10:31 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 7 ]
232
Feb 23 21:10:36 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=8 DATA len=42
233
Feb 23 21:10:36 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
234
Feb 23 21:10:36 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 8 ]
235
Feb 23 21:10:42 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=9 DATA len=42
236
Feb 23 21:10:42 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
237
Feb 23 21:10:42 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 9 ]
238
Feb 23 21:10:47 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=10 DATA len=42
239
Feb 23 21:10:47 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
240
Feb 23 21:10:47 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 10 ]
241
Feb 23 21:10:52 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=11 DATA len=42
242
Feb 23 21:10:52 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
243
Feb 23 21:10:52 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 11 ]
244
Feb 23 21:10:57 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=12 DATA len=42
245
Feb 23 21:10:57 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
246
Feb 23 21:10:57 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 12 ]
247
Feb 23 21:11:03 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=13 DATA len=42
248
Feb 23 21:11:03 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
249
Feb 23 21:11:03 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 13 ]
250
Feb 23 21:11:08 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=14 DATA len=42
251
Feb 23 21:11:08 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
252
Feb 23 21:11:08 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 14 ]
253
Feb 23 21:11:13 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=15 DATA len=42
254
Feb 23 21:11:13 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
255
Feb 23 21:11:13 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 15 ]
256
Feb 23 21:11:14 d0-nfw2533 openvpn[29675]: event_wait : Interrupted system call (code=4)
257
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [14] from [AF_INET]<client-ip>:43518: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0
258
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 TLS: new session incoming connection from [AF_INET]<client-ip>:43518
259
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [26] to [AF_INET]<client-ip>:43518: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0
260
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 0 ]
261
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [187] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=1 DATA len=173
262
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1200] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 1 ] pid=1 DATA len=1174
263
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1188] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=2 DATA len=1174
264
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [1188] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=3 DATA len=1174
265
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [510] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=496
266
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 1 ]
267
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 2 ]
268
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 3 ]
269
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [152] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 4 ] pid=2 DATA len=126
270
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [77] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 2 ] pid=5 DATA len=51
271
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [453] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 5 ] pid=3 DATA len=427
272
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_VER=2.4.4
273
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_PLAT=freebsd
274
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_PROTO=2
275
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_NCP=2
276
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZ4=1
277
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZ4v2=1
278
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_LZO=1
279
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_COMP_STUB=1
280
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_COMP_STUBv2=1
281
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 peer info: IV_TCPNL=1
282
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PLUGIN_CALL: POST /usr/local/lib/openvpn/plugins/openvpn-plugin-auth-script.so/PLUGIN_AUTH_USER_PASS_VERIFY status=2
283
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 TLS: Username/Password authentication deferred for username '<client-user>' [CN SET]
284
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 TLS: move_session: dest=TM_ACTIVE src=TM_UNTRUSTED reinit_src=1
285
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 TLS: tls_multi_process: untrusted session promoted to semi-trusted
286
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [252] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ 3 ] pid=6 DATA len=226
287
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [22] from [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 6 ]
288
Feb 23 21:11:23 d0-nfw2533 openvpn[29675]: <client-ip>:43518 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384
289
Feb 23 21:11:24 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=4 DATA len=42
290
Feb 23 21:11:24 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
291
Feb 23 21:11:24 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 4 ]
292
Feb 23 21:11:28 d0-nfw2533 openvpn[29675]: event_wait : Interrupted system call (code=4)
293
Feb 23 21:11:29 d0-nfw2533 openvpn[29675]: <client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=5 DATA len=42
294
Feb 23 21:11:29 d0-nfw2533 openvpn[29675]: <client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
295
Feb 23 21:11:29 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:43518 MULTI_sva: pool returned IPv4=172.29.128.2, IPv6=(Not enabled)
296
Feb 23 21:11:29 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:43518 WARNING: Failed running command (--client-connect): external program fork failed
297
Feb 23 21:11:29 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 5 ]
298
Feb 23 21:11:35 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:43518 UDPv4 READ [56] from [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=6 DATA len=42
299
Feb 23 21:11:35 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:43518 PUSH: Received control message: 'PUSH_REQUEST'
300
Feb 23 21:11:35 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:43518 Delayed exit in 5 seconds
301
Feb 23 21:11:35 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:43518 SENT CONTROL [<client-user>]: 'AUTH_FAILED' (status=1)
302
Feb 23 21:11:35 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:43518 UDPv4 WRITE [22] to [AF_INET]<client-ip>:43518: P_ACK_V1 kid=0 [ 6 ]
303
Feb 23 21:11:35 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:43518 UDPv4 WRITE [55] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=41
304
Feb 23 21:11:37 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:43518 UDPv4 WRITE [55] to [AF_INET]<client-ip>:43518: P_CONTROL_V1 kid=0 [ ] pid=7 DATA len=41
305
Feb 23 21:11:40 d0-nfw2533 openvpn[29675]: <client-user>/<client-ip>:43518 SIGTERM[soft,delayed-exit] received, client-instance exiting
(2-2/4)