Re: [Radiusplugin-users] PLUGIN_CLIENT_CONNECT failed

[Eike Lohmann]

Hi Ralf, hi List,

it took some time, but yesterday i got the error with verb 7 on one of my 
machines.
This machine has ~300 running clients and i tried to copy the relevant things,
without to grep for the IP:Source combination only.
It's nice to handle a >4GB Logfile, many tools can't open it.

Logfile is attached, thanks for any help.

"

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.

"


Am 08.02.2012 18:59, schrieb Ralf Lübben:
> Hi,
>
> still the plugin debugging information is missing. This could indicate why 
> the 
> connect fails.
>
> If you use an old version the verbosity level must be set to 7 .
>
> So your OpenVPN configuration file should contain
>
> verb 7
> log /var/log/openvpn.log 
>
> The plugin writes debugging information to stderr, as described in the man 
> page of OpenVPN this is forwarded to the configured log file. 
>
> Can you check your settings? If you use syslog the debugging will probably be 
> redirected to /dev/null .
>
> Ralf
>
>
>
>
> Am Mittwoch, 8. Februar 2012, 09:17:44 schrieb 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

OpenVPN_verb7_Radiusplugin_Problem.log
Description: Text Data