[Top][All Lists]
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
RE: [Radiusplugin-users] IAS Accounting not working
|
From: |
Tom Stage |
|
Subject: |
RE: [Radiusplugin-users] IAS Accounting not working |
|
Date: |
Thu, 2 Apr 2009 14:13:09 +0200 |
Hi Ralf
Thanks for your quick reply
I can see 3 OpenVPN proccesses, and here is my new log file:
Thu Apr 2 14:05:44 2009 us=299726 OpenVPN 2.0.9 x86_64-redhat-linux-gnu [SSL]
[LZO] [EPOLL] built on Mar 8 2007
Thu Apr 2 14:05:44 2009 us=299798 MANAGEMENT: TCP Socket listening on
127.0.0.1:7505
RADIUS-PLUGIN: Start AUTH-RADIUS-PLUGIN
RADIUS-PLUGIN: Found 2 params.
RADIUS-PLUGIN: Find params.
RADIUS-PLUGIN: Configfile name: /etc/openvpn/radiusplugin.cnf .
RADIUS-PLUGIN: BACKGROUND AUTH: Started, RESPONSE_INIT_SUCCEEDED was sent to
Foreground Process.
RADIUS-PLUGIN: Start BACKGROUND Process for authentication with PID 30807
RADIUS-PLUGIN: Start AUTH-RADIUS-PLUGIN
RADIUS-PLUGIN: Start BACKGROUND Process for accounting
RADIUS-PLUGIN: BACKGROUND ACCT: Started, RESPONSE_INIT_SUCCEEDED was sent to
Foreground Process.
RADIUS-PLUGIN: Start BACKGROUND Process for accounting with PID 30808
RADIUS-PLUGIN: Start AUTH-RADIUS-PLUGIN
Thu Apr 2 14:05:44 2009 us=305361 PLUGIN_INIT: POST
/etc/openvpn/radiusplugin.so '/etc/openvpn/radiusplugin.cnf'
intercepted=PLUGIN_AUTH_USER_PASS_VERIFY|PLUGIN_CLIENT_CONNECT|PLUGIN_CLIENT_DISCONNECT
Thu Apr 2 14:05:44 2009 us=305402 NOTE: --fast-io is disabled since we are not
using UDP
Thu Apr 2 14:05:44 2009 us=333758 Diffie-Hellman initialized with 2048 bit key
Thu Apr 2 14:05:44 2009 us=334079 WARNING: file 'keys/decon/deconvpn.key' is
group or others accessible
Thu Apr 2 14:05:44 2009 us=334592 WARNING: file 'servers/Decon_VPN/ta.key' is
group or others accessible
Thu Apr 2 14:05:44 2009 us=334610 Control Channel Authentication: using
'servers/Decon_VPN/ta.key' as a OpenVPN static key file
Thu Apr 2 14:05:44 2009 us=334634 Outgoing Control Channel Authentication:
Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Apr 2 14:05:44 2009 us=334650 Incoming Control Channel Authentication:
Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Apr 2 14:05:44 2009 us=334678 TLS-Auth MTU parms [ L:1544 D:168 EF:68 EB:0
ET:0 EL:0 ]
Thu Apr 2 14:05:44 2009 us=335867 TUN/TAP device tun0 opened
Thu Apr 2 14:05:44 2009 us=335909 TUN/TAP TX queue length set to 100
Thu Apr 2 14:05:44 2009 us=335950 /sbin/ip link set dev tun0 up mtu 1500
Thu Apr 2 14:05:44 2009 us=343268 /sbin/ip addr add dev tun0 local 10.0.10.1
peer 10.0.10.2
Thu Apr 2 14:05:44 2009 us=349897 /sbin/ip route add 10.0.10.0/24 via 10.0.10.2
Thu Apr 2 14:05:44 2009 us=352756 Data Channel MTU parms [ L:1544 D:1400 EF:44
EB:135 ET:0 EL:0 AF:3/1 ]
Thu Apr 2 14:05:44 2009 us=353532 GID set to adm
Thu Apr 2 14:05:44 2009 us=353585 UID set to nobody
Thu Apr 2 14:05:44 2009 us=353630 Listening for incoming TCP connection on
10.0.0.6:1194
Thu Apr 2 14:05:44 2009 us=353665 Socket Buffers: R=[87380->131072]
S=[16384->131072]
Thu Apr 2 14:05:44 2009 us=353688 TCPv4_SERVER link local (bound):
10.0.0.6:1194
Thu Apr 2 14:05:44 2009 us=353702 TCPv4_SERVER link remote: [undef]
Thu Apr 2 14:05:44 2009 us=353727 MULTI: multi_init called, r=256 v=256
Thu Apr 2 14:05:44 2009 us=353775 IFCONFIG POOL: base=10.0.10.4 size=62
Thu Apr 2 14:05:44 2009 us=353835 IFCONFIG POOL LIST
Thu Apr 2 14:05:44 2009 us=353850 decon,10.0.10.4
Thu Apr 2 14:05:44 2009 us=353864 bjarne_vpn,10.0.10.8
Thu Apr 2 14:05:44 2009 us=353877 tom_vpn,10.0.10.12
Thu Apr 2 14:05:44 2009 us=353889 rene_vpn,10.0.10.16
Thu Apr 2 14:05:44 2009 us=353914 MULTI: TCP INIT maxclients=100 maxevents=104
Thu Apr 2 14:05:44 2009 us=353950 Initialization Sequence Completed
Thu Apr 2 14:06:01 2009 us=216039 MULTI: multi_create_instance called
Thu Apr 2 14:06:01 2009 us=216112 Re-using SSL/TLS context
Thu Apr 2 14:06:01 2009 us=216167 LZO compression initialized
Thu Apr 2 14:06:01 2009 us=216353 Control Channel MTU parms [ L:1544 D:168
EF:68 EB:0 ET:0 EL:0 ]
Thu Apr 2 14:06:01 2009 us=216392 Data Channel MTU parms [ L:1544 D:1400 EF:44
EB:135 ET:0 EL:0 AF:3/1 ]
Thu Apr 2 14:06:01 2009 us=216455 Local Options String: 'V4,dev-type
tun,link-mtu 1544,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,keydir 0,cipher
DES-CBC,auth SHA1,keysize 64,tls-auth,key-method 2,tls-server'
Thu Apr 2 14:06:01 2009 us=216471 Expected Remote Options String: 'V4,dev-type
tun,link-mtu 1544,tun-mtu 1500,proto TCPv4_CLIENT,comp-lzo,keydir 1,cipher
DES-CBC,auth SHA1,keysize 64,tls-auth,key-method 2,tls-client'
Thu Apr 2 14:06:01 2009 us=216509 Local Options hash (VER=V4): '5e56b428'
Thu Apr 2 14:06:01 2009 us=216531 Expected Remote Options hash (VER=V4):
'64fc6ce3'
Thu Apr 2 14:06:01 2009 us=216569 TCP connection established with
80.251.195.2:23998
Thu Apr 2 14:06:01 2009 us=216589 Socket Buffers: R=[131072->131072]
S=[131072->131072]
Thu Apr 2 14:06:01 2009 us=216607 TCPv4_SERVER link local: [undef]
Thu Apr 2 14:06:01 2009 us=216622 TCPv4_SERVER link remote: 80.251.195.2:23998
WRThu Apr 2 14:06:01 2009 us=354329 80.251.195.2:23998 TLS: Initial packet
from 80.251.195.2:23998, sid=7e9fc0ed c604b2a7
WRWRRWWWWRWRWRWWRWRWRWWRWRWWWWWWRWRRWWRWRRRRWWWWRWRWRWWRWRWRWRWRWRWRWRRRRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRWRThu
Apr 2 14:06:12 2009 us=39853 80.251.195.2:23998 CRL CHECK OK:
/C=DK/ST=CPH/L=Copenhagen/O=Decon_Aps./address@hidden
Thu Apr 2 14:06:12 2009 us=39899 80.251.195.2:23998 VERIFY OK: depth=1,
/C=DK/ST=CPH/L=Copenhagen/O=Decon_Aps./address@hidden
Thu Apr 2 14:06:12 2009 us=40265 80.251.195.2:23998 CRL CHECK OK:
/C=DK/ST=CPH/L=Copenhagen/O=Decon_Aps./OU=Office/CN=tom_vpn/address@hidden
Thu Apr 2 14:06:12 2009 us=40298 80.251.195.2:23998 VERIFY OK: depth=0,
/C=DK/ST=CPH/L=Copenhagen/O=Decon_Aps./OU=Office/CN=tom_vpn/address@hidden
WRWRWRWRWRWRWRWRWRWRRADIUS-PLUGIN: FOREGROUND:
OPENVPN_PLUGIN_AUTH_USER_PASS_VERIFY is called.
RADIUS-PLUGIN: FOREGROUND: New user: username: ths, password: *****, newuser
ip: 80.251.195.2, newuser port: 23998 .
RADIUS-PLUGIN: BACKGROUND AUTH: New user auth: username: ths, password: *****,
calling station: 80.251.195.2, commonname: tom_vpn.
RADIUS-PLUGIN: radius_server().
RADIUS-PLUGIN: Build password packet: password: *****, sharedSecret: *****.
RADIUS-PLUGIN: Send packet to 10.0.0.5.
RADIUS-PLUGIN: Get ACCESS_ACCEPT-Packet.
RADIUS-PLUGIN: parse_response_packet().
RADIUS-PLUGIN: BACKGROUND AUTH: routes: .
RADIUS-PLUGIN: BACKGROUND AUTH: framed ip: .
RADIUS-PLUGIN: No attributes Acct Interim Interval or bad length.
RADIUS-PLUGIN: BACKGROUND AUTH: Acct Interim Interval: 0.
RADIUS-PLUGIN: BACKGROUND AUTH: Try to open ccd file.
RADIUS-PLUGIN: BACKGROUND AUTH: Opened ccd file.
RADIUS-PLUGIN: FOREGROUND: Authentication succeeded!
RADIUS-PLUGIN: FOREGROUND: Received routes for user: .
RADIUS-PLUGIN: FOREGROUND: Received framed ip for user: .
RADIUS-PLUGIN: FOREGROUND: Receive acctinteriminterval 0 sec from
backgroundprocess.
RADIUS-PLUGIN: FOREGROUND: Add user to map.
Thu Apr 2 14:06:12 2009 us=992539 80.251.195.2:23998 PLUGIN_CALL: POST
/etc/openvpn/radiusplugin.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0
Thu Apr 2 14:06:12 2009 us=992563 80.251.195.2:23998 TLS: Username/Password
authentication succeeded for username 'ths'
Thu Apr 2 14:06:12 2009 us=992726 80.251.195.2:23998 Data Channel Encrypt:
Cipher 'DES-CBC' initialized with 64 bit key
Thu Apr 2 14:06:12 2009 us=992745 80.251.195.2:23998 Data Channel Encrypt:
Using 160 bit message hash 'SHA1' for HMAC authentication
Thu Apr 2 14:06:12 2009 us=992761 80.251.195.2:23998 Data Channel Decrypt:
Cipher 'DES-CBC' initialized with 64 bit key
Thu Apr 2 14:06:12 2009 us=992777 80.251.195.2:23998 Data Channel Decrypt:
Using 160 bit message hash 'SHA1' for HMAC authentication
WWWRADIUS-PLUGIN: BACKGROUND AUTH: Auth succeeded in radius_server().
RRThu Apr 2 14:06:13 2009 us=467924 80.251.195.2:23998 Control Channel: TLSv1,
cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Thu Apr 2 14:06:13 2009 us=467969 80.251.195.2:23998 [tom_vpn] Peer Connection
Initiated with 80.251.195.2:23998
Thu Apr 2 14:06:13 2009 us=468033 tom_vpn/80.251.195.2:23998 OPTIONS IMPORT:
reading client specific options from: /etc/openvpn/servers/Decon_VPN/ccd/tom_vpn
RADIUS-PLUGIN: FOREGROUND: OPENVPN_PLUGIN_CLIENT_CONNECT is called.
RADIUS-PLUGIN: FOREGROUND: Set FramedIP to the IP (10.0.10.14) OpenVPN assigned
to the user ths
RADIUS-PLUGIN: FOREGROUND: Add user for accounting: username: ths, commonname:
tom_vpn
RADIUS-PLUGIN: BACKGROUND ACCT: Get a command.
RADIUS-PLUGIN: BACKGROUND ACCT: New User.
RADIUS-PLUGIN: BACKGROUND ACCT: New user acct: username: ths, interval: 0,
calling station: 80.251.195.2, commonname: tom_vpn, framed ip: 10.0.10.14.
RADIUS-PLUGIN: BACKGROUND-ACCT: Get ACCOUNTING_RESPONSET-Packet.
RADIUS-PLUGIN: BACKGROUND ACCT: Start packet was send.
RADIUS-PLUGIN: BACKGROUND ACCT: User was added to accounting scheduler.
RADIUS-PLUGIN: BACKGROUND-ACCT: No routes for user.
RADIUS-PLUGIN: FOREGROUND: Accouting succeeded!
Thu Apr 2 14:06:13 2009 us=470137 tom_vpn/80.251.195.2:23998 PLUGIN_CALL: POST
/etc/openvpn/radiusplugin.so/PLUGIN_CLIENT_CONNECT status=0
Thu Apr 2 14:06:13 2009 us=470192 tom_vpn/80.251.195.2:23998 MULTI: Learn:
10.0.10.14 -> tom_vpn/80.251.195.2:23998
Thu Apr 2 14:06:13 2009 us=470212 tom_vpn/80.251.195.2:23998 MULTI: primary
virtual IP for tom_vpn/80.251.195.2:23998: 10.0.10.14
RThu Apr 2 14:06:14 2009 us=519160 tom_vpn/80.251.195.2:23998 PUSH: Received
control message: 'PUSH_REQUEST'
Thu Apr 2 14:06:14 2009 us=519211 tom_vpn/80.251.195.2:23998 SENT CONTROL
[tom_vpn]: 'PUSH_REPLY,dhcp-option DNS 10.0.0.5,dhcp-option WINS 10.0.0.5,route
10.0.0.0 255.255.255.0,route 10.0.10.1,ping 10,ping-restart 120,ifconfig
10.0.10.14 10.0.10.13' (status=1)
WWWWRRRwRwWRwRwRwRwWRwRwRwW
From what i can see it says that accounting is a success, aparently there is no
problem after all, or what?
Cheers
Tom Stage
----- Original Message -----
From: Ralf Lübben <address@hidden>
Sent: Thu, 2/4/2009 12:50
To: address@hidden
Cc: Tom Stage <address@hidden>
Subject: Re: [Radiusplugin-users] IAS Accounting not working
Hi,
the log seems to be o.k. so far.
Can you increase your OpenVPN verbosity level to 5? And send it again.
Can you check if all OpenVPN processes are running? You should see 3
processes.
Ralf
On Thursday 02 April 2009 12:23:40 Tom Stage wrote:
> Hi All
>
> Iam trying to get the Radiusplugin for OpenVPN to work with our Windows
> 2003 AD server using IAS.
>
> Versions:
> CentOS 5.x
> OpenVPN 2.0.9 x86_64-redhat-linux-gnu [SSL] [LZO] [EPOLL] built on Mar 8
> 2007 Radiusplugin v2.0c
> Windows 2003 R2 fully updated.
>
> OpenVPN Server config:
> port 1194
> proto tcp-server
> dev tun0
> fast-io
> ca keys/decon/ca.crt
> cert keys/decon/deconvpn.crt
> key keys/decon/deconvpn.key
> dh keys/decon/dh2048.pem
> server 10.0.10.0 255.255.255.0
> crl-verify keys/decon/crl.pem
> ifconfig-pool-persist servers/Decon_VPN/logs/ipp.txt
> tls-auth servers/Decon_VPN/ta.key 0
> cipher DES-CBC
> user nobody
> group adm
> status servers/Decon_VPN/logs/openvpn-status.log
> log-append servers/Decon_VPN/logs/openvpn.log
> verb 3
> mute 20
> max-clients 100
> mssfix 1400
> local 10.0.0.6
> management 127.0.0.1 7505
> keepalive 10 120
> client-config-dir /etc/openvpn/servers/Decon_VPN/ccd
> tls-server
> comp-lzo
> persist-key
> persist-tun
> ccd-exclusive
> plugin /etc/openvpn/radiusplugin.so /etc/openvpn/radiusplugin.cnf
> push "dhcp-option DNS 10.0.0.5"
> push "dhcp-option WINS 10.0.0.5"
> push "route 10.0.0.0 255.255.255.0"
>
> Radiusplugin config:
> NAS-Identifier=OpenVpn
> Service-Type=5
> Framed-Protocol=1
> NAS-Port-Type=5
> NAS-IP-Address=10.0.0.6
> OpenVPNConfig=/etc/openvpn/Decon_VPN.conf
> overwriteccfiles=true
> server
> {
> acctport=1813
> authport=1812
> name=10.0.0.5
> retry=3
> wait=3
> sharedsecret=secret
> }
>
> OpenVPN Client config:
> client
> proto tcp-client
> dev tun
> ca ca.crt
> dh dh2048.pem
> cert tom_vpn.crt
> key tom_vpn.key
> remote 90.184.139.227 1194
> tls-auth ta.key 1
> cipher DES-CBC
> verb 2
> mute 20
> mssfix 1400
> keepalive 10 120
> comp-lzo
> persist-key
> persist-tun
> float
> resolv-retry infinite
> nobind
> ns-cert-type server
> auth-user-pass
>
> When i connect with my clients they get the following in the OpenVPN log
> file: Thu Apr 2 10:00:44 2009 Initialization Sequence Completed
> Thu Apr 2 10:29:04 2009 MULTI: multi_create_instance called
> Thu Apr 2 10:29:04 2009 Re-using SSL/TLS context
> Thu Apr 2 10:29:04 2009 LZO compression initialized
> Thu Apr 2 10:29:04 2009 Control Channel MTU parms [ L:1544 D:168 EF:68
> EB:0 ET:0 EL:0 ] Thu Apr 2 10:29:04 2009 Data Channel MTU parms [ L:1544
> D:1400 EF:44 EB:135 ET:0 EL:0 AF:3/1 ] Thu Apr 2 10:29:04 2009 Local
> Options hash (VER=V4): '5e56b428'
> Thu Apr 2 10:29:04 2009 Expected Remote Options hash (VER=V4): '64fc6ce3'
> Thu Apr 2 10:29:04 2009 TCP connection established with
> 80.251.195.31:59217 Thu Apr 2 10:29:04 2009 TCPv4_SERVER link local:
> [undef]
> Thu Apr 2 10:29:04 2009 TCPv4_SERVER link remote: 80.251.195.31:59217
> Thu Apr 2 10:29:04 2009 80.251.195.31:59217 TLS: Initial packet from
> 80.251.195.31:59217, sid=085fc3a6 15cd388e Thu Apr 2 10:29:09 2009
> 80.251.195.31:59217 CRL CHECK OK:
> /C=DK/ST=CPH/L=Copenhagen/O=Decon_Aps./address@hidden Thu Apr 2
> 10:29:09 2009 80.251.195.31:59217 VERIFY OK: depth=1,
> /C=DK/ST=CPH/L=Copenhagen/O=Decon_Aps./address@hidden Thu Apr 2
> 10:29:09 2009 80.251.195.31:59217 CRL CHECK OK:
> /C=DK/ST=CPH/L=Copenhagen/O=Decon_Aps./OU=Office/CN=tom_vpn/emailAddress=th
>address@hidden Thu Apr 2 10:29:09 2009 80.251.195.31:59217 VERIFY OK: depth=0,
> /C=DK/ST=CPH/L=Copenhagen/O=Decon_Aps./OU=Office/CN=tom_vpn/emailAddress=th
>address@hidden RADIUS-PLUGIN: No attributes Acct Interim Interval or bad
>length.
> RADIUS-PLUGIN: FOREGROUND: Add user to map.
> Thu Apr 2 10:29:10 2009 80.251.195.31:59217 PLUGIN_CALL: POST
> /etc/openvpn/radiusplugin.so/PLUGIN_AUTH_USER_PASS_VERIFY status=0 Thu Apr
> 2 10:29:10 2009 80.251.195.31:59217 TLS: Username/Password authentication
> succeeded for username 'ths' Thu Apr 2 10:29:10 2009 80.251.195.31:59217
> Data Channel Encrypt: Cipher 'DES-CBC' initialized with 64 bit key Thu Apr
> 2 10:29:10 2009 80.251.195.31:59217 Data Channel Encrypt: Using 160 bit
> message hash 'SHA1' for HMAC authentication Thu Apr 2 10:29:10 2009
> 80.251.195.31:59217 Data Channel Decrypt: Cipher 'DES-CBC' initialized with
> 64 bit key Thu Apr 2 10:29:10 2009 80.251.195.31:59217 Data Channel
> Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication Thu Apr
> 2 10:29:11 2009 80.251.195.31:59217 Control Channel: TLSv1, cipher
> TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA Thu Apr 2 10:29:11 2009
> 80.251.195.31:59217 [tom_vpn] Peer Connection Initiated with
> 80.251.195.31:59217 Thu Apr 2 10:29:11 2009 tom_vpn/80.251.195.31:59217
> OPTIONS IMPORT: reading client specific options from:
> /etc/openvpn/servers/Decon_VPN/ccd/tom_vpn Thu Apr 2 10:29:11 2009
> tom_vpn/80.251.195.31:59217 PLUGIN_CALL: POST
> /etc/openvpn/radiusplugin.so/PLUGIN_CLIENT_CONNECT status=0 Thu Apr 2
> 10:29:11 2009 tom_vpn/80.251.195.31:59217 MULTI: Learn: 10.0.10.14 ->
> tom_vpn/80.251.195.31:59217 Thu Apr 2 10:29:11 2009
> tom_vpn/80.251.195.31:59217 MULTI: primary virtual IP for
> tom_vpn/80.251.195.31:59217: 10.0.10.14 Thu Apr 2 10:29:12 2009
> tom_vpn/80.251.195.31:59217 PUSH: Received control message: 'PUSH_REQUEST'
> Thu Apr 2 10:29:12 2009 tom_vpn/80.251.195.31:59217 SENT CONTROL
> [tom_vpn]: 'PUSH_REPLY,dhcp-option DNS 10.0.0.5,dhcp-option WINS
> 10.0.0.5,route 10.0.0.0 255.255.255.0,route 10.0.10.1,ping 10,ping-restart
> 120,ifconfig 10.0.10.14 10.0.10.13' (status=1)
>
> Iam not sure what i do wrong so i anybody can point me in the right
> direction that would be great.
>
> Cheers
> Tom Stage