Re: [Radiusplugin-users] PLUGIN_CLIENT_CONNECT failed

[Eike Lohmann]

Good Morning,

with verb 5 i got this information only, authentication is ok, but accounting
fails or?

Thanks, Eike

Feb  7 00:56:05 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Re-using
SSL/TLS context
Feb  7 00:56:05 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 LZO
compression initialized
Feb  7 00:56:05 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Control
Channel MTU parms [ L:1546 D:138 EF:38 EB:0 ET:0 EL:0 ]
Feb  7 00:56:05 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Data Channel
MTU parms [ L:1546 D:1300 EF:46 EB:135 ET:0 EL:0 AF:3/1 ]
Feb  7 00:56:05 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Fragmentation
MTU parms [ L:1546 D:1300 EF:45 EB:135 ET:1 EL:0 AF:3/1 ]
Feb  7 00:56:05 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Local Options
String: 'V4,dev-type tun,link-mtu 1546,tun-mtu 1500,proto
UDPv4,comp-lzo,mtu-dynamic,cipher BF-CBC,auth SHA1,keysize 128,key-method
2,tls-server'
Feb  7 00:56:05 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Expected
Remote Options String: 'V4,dev-type tun,link-mtu 1546,tun-mtu 1500,proto
UDPv4,comp-lzo,mtu-dynamic,cipher BF-CBC,auth SHA1,keysize 128,key-method
2,tls-client'
Feb  7 00:56:05 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Local Options
hash (VER=V4): '8e7959c7'
Feb  7 00:56:05 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Expected
Remote Options hash (VER=V4): 'c086e1aa'
Feb  7 00:56:05 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 TLS: Initial
packet from [AF_INET]87.106.xxx.xxx:60378, sid=b7748434 01d2d4b4
Feb  7 00:56:20 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 PLUGIN_CALL:
POST /etc/openvpn/radiusplugin.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0
Feb  7 00:56:20 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 TLS:
Username/Password authentication succeeded for username 'user1234' [CN SET]
Feb  7 00:56:20 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Data Channel
Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Feb  7 00:56:20 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Data Channel
Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Feb  7 00:56:20 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Data Channel
Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Feb  7 00:56:20 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Data Channel
Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Feb  7 00:56:20 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 Control
Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA
Feb  7 00:56:20 ovpn-server ovpn-ovpnd[1193]: 87.106.xxx.xxx:60378 [user1234]
Peer Connection Initiated with [AF_INET]87.106.xxx.xxx:60378
Feb  7 00:56:20 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378
OPTIONS IMPORT: reading client specific options from: /etc/openvpn/ccd/user1234
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378
PLUGIN_CALL: POST /etc/openvpn/radiusplugin.so/PLUGIN_CLIENT_CONNECT status=1
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378
PLUGIN_CALL: plugin function PLUGIN_CLIENT_CONNECT failed with status 1:
/etc/openvpn/radiusplugin.so
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378
WARNING: client-connect plugin call failed
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378
PUSH: Received control message: 'PUSH_REQUEST'
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378
Delayed exit in 5 seconds
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378 SENT
CONTROL [user1234]: 'AUTH_FAILED' (status=1)
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378
PUSH: Received control message: 'PUSH_REQUEST'
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378
Delayed exit in 5 seconds
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378 SENT
CONTROL [user1234]: 'AUTH_FAILED' (status=1)
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378
PUSH: Received control message: 'PUSH_REQUEST'
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378
Delayed exit in 5 seconds
Feb  7 00:56:36 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378 SENT
CONTROL [user1234]: 'AUTH_FAILED' (status=1)
Feb  7 00:56:42 ovpn-server ovpn-ovpnd[1193]: user1234/87.106.xxx.xxx:60378
SIGTERM[soft,delayed-exit] received, client-instance exiting


Am 04.02.2012 14:40, schrieb Ralf Lübben:
> Hi,
>
> the plugin output is missing. 
>
> Usally the plugin writes logging information to the OpenVPN log file, if the 
> verb option is greater or equal 5. This information is missing in the log 
> files. The information starts with "RADIUS-PLUGIN: ...". 
>
> Can you try to create files with the logging information of the plugin. 
> (I don't know why it is missing in your file.)
>
>
> Ralf
>
>  
>
>
>
>
> Am Freitag, 3. Februar 2012, 10:28:59 schrieb Eike Lohmann:
>> Hi Ralf, hi List,
>>
>> here the ovpnlog with verbose 7.
>> I have obfuscated IP and Keyvalues and hope that 'mute' didn't captured the
>> interesting lines, otherwise I have to capture again.
>>
>> Thanks for the help.
>>
>> Am 31.01.2012 16:38, schrieb Ralf Lübben:
>>> Hi,
>>>
>>> can you increase the verbosity level  to 7 in OpenVPN config and post
>>> the
>>> output again?
>>>
>>> Probably it shows why CLIENT_CONNECT fails.
>>>
>>> Regards,
>>> Ralf
>>>
>>> Am Dienstag, 31. Januar 2012, 13:52:20 schrieb Eike Lohmann:
>>>> Hi Ralf, hi List,
>>>>
>>>> sometimes a client failed to connect and stop reconnecting and I can't
>>>> find the reason for this behavior.
>>>> If I look into my Radius, the client got authenticated and accounting
>>>> START was created.
>>>>
>>>> Any Ideas? I have 2 radius servers (http://www.open.com.au/radiator/)
>>>> and this happens only with one of them.
>>>>
>>>> My openvpnlog:
>>>>
>>>> Jan 31 00:15:41 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492
>>>> Re-using SSL/TLS context
>>>> Jan 31 00:15:41 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492 LZO
>>>> compression initialized
>>>> Jan 31 00:15:41 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492
>>>> Control Channel MTU parms [ L:1546 D:138 EF:38 EB:0 ET:0 EL:0 ]
>>>> Jan 31 00:15:41 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492 Data
>>>> Channel MTU parms [ L:1546 D:1300 EF:46 EB:135 ET:0 EL:0 AF:3/1 ]
>>>> Jan 31 00:15:41 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492
>>>> Fragmentation MTU parms [ L:1546 D:1300 EF:45 EB:135 ET:1 EL:0 AF:3/1
>>>> ]
>>>> Jan 31 00:15:41 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492
>>>> Local
>>>> Options hash (VER=V4): '8e7959c7'
>>>> Jan 31 00:15:41 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492
>>>> Expected Remote Options hash (VER=V4): 'c086e1aa'
>>>> Jan 31 00:15:41 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492 TLS:
>>>> Initial packet from [AF_INET]178.14.xx.xxx:51492, sid=81322596
>>>> 0617b1b6
>>>> Jan 31 00:15:45 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492
>>>> PLUGIN_CALL: POST
>>>> /etc/openvpn/radiusplugin.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0
>>>> Jan 31 00:15:45 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492
>>>> TLS: Username/Password authentication succeeded for username
>>>> 'user1234' [CN SET] Jan 31 00:15:45 ovpn-server ovpn-ovpnd[1002]:
>>>> 178.14.xx.xxx:51492 Data Channel Encrypt: Cipher 'BF-CBC' initialized
>>>> with 128 bit key
>>>> Jan 31 00:15:45 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492 Data
>>>> Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC
>>>> authentication Jan 31 00:15:45 ovpn-server ovpn-ovpnd[1002]:
>>>> 178.14.xx.xxx:51492 Data Channel Decrypt: Cipher 'BF-CBC' initialized
>>>> with 128 bit key
>>>> Jan 31 00:15:45 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492 Data
>>>> Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC
>>>> authentication Jan 31 00:15:45 ovpn-server ovpn-ovpnd[1002]:
>>>> 178.14.xx.xxx:51492 Control Channel: TLSv1, cipher TLSv1/SSLv3
>>>> DHE-RSA-AES256-SHA
>>>> Jan 31 00:15:45 ovpn-server ovpn-ovpnd[1002]: 178.14.xx.xxx:51492
>>>> [user1234] Peer Connection Initiated with
>>>> [AF_INET]178.14.xx.xxx:51492
>>>> Jan 31 00:15:45 ovpn-server ovpn-ovpnd[1002]:
>>>> user1234/178.14.xx.xxx:51492 OPTIONS IMPORT: reading client specific
>>>> options from:
>>>> /etc/openvpn/ccd/user1234 Jan 31 00:15:56 ovpn-server
>>>> ovpn-ovpnd[1002]:
>>>> user1234/178.14.xx.xxx:51492 PLUGIN_CALL: POST
>>>> /etc/openvpn/radiusplugin.so/PLUGIN_CLIENT_CONNECT status=1 Jan 31
>>>> 00:15:56 ovpn-server ovpn-ovpnd[1002]: user1234/178.14.xx.xxx:51492
>>>> PLUGIN_CALL: plugin function PLUGIN_CLIENT_CONNECT failed with status
>>>> 1:
>>>> /etc/openvpn/radiusplugin.so
>>>> Jan 31 00:15:56 ovpn-server ovpn-ovpnd[1002]:
>>>> user1234/178.14.xx.xxx:51492 WARNING: client-connect plugin call
>>>> failed
>>>> Jan 31 00:15:56 ovpn-server ovpn-ovpnd[1002]:
>>>> user1234/178.14.xx.xxx:51492 PUSH: Received control message:
>>>> 'PUSH_REQUEST'
>>>> Jan 31 00:15:56 ovpn-server ovpn-ovpnd[1002]:
>>>> user1234/178.14.xx.xxx:51492 Delayed exit in 5 seconds
>>>> Jan 31 00:15:56 ovpn-server ovpn-ovpnd[1002]:
>>>> user1234/178.14.xx.xxx:51492 SENT CONTROL [user1234]: 'AUTH_FAILED'
>>>> (status=1)
>>>> Jan 31 00:15:56 ovpn-server ovpn-ovpnd[1002]:
>>>> user1234/178.14.xx.xxx:51492 PUSH: Received control message:
>>>> 'PUSH_REQUEST'
>>>> Jan 31 00:15:56 ovpn-server ovpn-ovpnd[1002]:
>>>> user1234/178.14.xx.xxx:51492 Delayed exit in 5 seconds
>>>> Jan 31 00:15:56 ovpn-server ovpn-ovpnd[1002]:
>>>> user1234/178.14.xx.xxx:51492 SENT CONTROL [user1234]: 'AUTH_FAILED'
>>>> (status=1)
>>>> Jan 31 00:16:01 ovpn-server ovpn-ovpnd[1002]:
>>>> user1234/178.14.xx.xxx:51492 SIGTERM[soft,delayed-exit] received,
>>>> client-instance exiting
>>>>
>>>>
>>>> A question maybe to the wrong List, but this client has disconnected
>>>> at
>>>> 18:58 on 30.1. and the server is "Re-using" the SSL/TLS context for
>>>> this
>>>> client. OK, reneg-sec = 86400 but I thought ping-*, keepalive or
>>>> explicit-exit-notify will destroy this context.
>>>>
>>>> Regards, Eike
>>>>
>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> Radiusplugin-users mailing list
>>>> address@hidden
>>>> https://lists.nongnu.org/mailman/listinfo/radiusplugin-users