ip address allocated but soon released
yata
aurens.memuro02 at gmail.com
Mon Apr 28 23:34:10 CEST 2014
I will put an additional log.It was gotten same situation.
Any advice will help me!
-----------------radiusd -X---------------------
Listening on authentication address * port 1812
Listening on accounting address * port 1813
Listening on command file /var/run/radiusd/radiusd.sock
Listening on authentication address 127.0.0.1 port 18120 as server
inner-tunnel
Listening on proxy address * port 1814
Ready to process requests.
rad_recv: Access-Request packet from host 10.0.5.200 port 50000, id=9,
length=205
User-Password = "test"
User-Name = "user at mondomaine.fr"
Acct-Session-Id = "erx FastEthernet 1/6:0012582922"
Service-Type = Framed-User
Framed-Protocol = PPP
ERX-Pppoe-Description = "pppoe 00:1d:72:c6:7b:d5"
Calling-Station-Id = "#ERX-40-b0-7a#E16#0"
NAS-Port-Type = Ethernet
NAS-Port = 369098752
NAS-Port-Id = "FastEthernet 1/6"
NAS-IP-Address = 10.0.5.200
NAS-Identifier = "ERX-40-b0-7a"
# Executing section authorize from file /etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[suffix] Looking up realm "mondomaine.fr" for User-Name = "
user at mondomaine.fr"
[suffix] No such realm "mondomaine.fr"
++[suffix] returns noop
[eap] No EAP-Message, not doing EAP
++[eap] returns noop
[files] users: Matched entry DEFAULT at line 1
[files] users: Matched entry user at mondomaine.fr at line 10
[files] users: Matched entry DEFAULT at line 187
++[files] returns ok
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns updated
Found Auth-Type = PAP
# Executing group from file /etc/raddb/sites-enabled/default
+- entering group PAP {...}
[pap] login attempt with password "test"
[pap] Using clear text password "test"
[pap] User authenticated successfully
++[pap] returns ok
Login OK: [user at mondomaine.fr] (from client GGSN1 port 369098752 cli
#ERX-40-b0-7a#E16#0)
# Executing section post-auth from file /etc/raddb/sites-enabled/default
+- entering group post-auth {...}
rlm_sql (sql): Reserving sql socket id: 13
[sqlippool] expand: %{User-Name} -> user at mondomaine.fr
[sqlippool] sql_set_user escaped user --> 'user at mondomaine.fr'
[sqlippool] expand: START TRANSACTION -> START TRANSACTION
[sqlippool] expand: UPDATE radippool SET nasipaddress = '', pool_key
= 0, callingstationid = '', username = '', expiry_time = NULL WHERE
expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress =
'%{Nas-IP-Address}' -> UPDATE radippool SET nasipaddress = '', pool_key =
0, callingstationid = '', username = '', expiry_time = NULL WHERE
expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = '10.0.5.200'
[sqlippool] expand: SELECT framedipaddress FROM radippool WHERE
pool_name = '%{control:Pool-Name}' AND (expiry_time < NOW() OR expiry_time
IS NULL) ORDER BY (username <> '%{User-Name}'), (callingstationid <>
'%{Calling-Station-Id}'), expiry_time LIMIT 1 FOR UPDATE -> SELECT
framedipaddress FROM radippool WHERE pool_name = 'pool1' AND (expiry_time
< NOW() OR expiry_time IS NULL) ORDER BY (username <> 'user at mondomaine.fr'),
(callingstationid <> '=23ERX-40-b0-7a=23E16=230'), expiry_time LIMIT 1
FOR UPDATE
[sqlippool] expand: UPDATE radippool SET nasipaddress =
'%{NAS-IP-Address}', pool_key = '%{NAS-Port}', callingstationid =
'%{Calling-Station-Id}', username = '%{User-Name}', expiry_time = NOW() +
INTERVAL 3600 SECOND WHERE framedipaddress = '192.168.0.1' AND expiry_time
IS NULL -> UPDATE radippool SET nasipaddress = '10.0.5.200', pool_key =
'369098752', callingstationid = '=23ERX-40-b0-7a=23E16=230', username = '
user at mondomaine.fr', expiry_time = NOW() + INTERVAL 3600 SECOND WHERE
framedipaddress = '192.168.0.1' AND expiry_time IS NULL
[sqlippool] Allocated IP 192.168.0.1 [0100a8c0]
[sqlippool] expand: COMMIT -> COMMIT
rlm_sql (sql): Released sql socket id: 13
[sqlippool] expand: Allocated IP: %{reply:Framed-IP-Address} from
%{control:Pool-Name} (did %{Called-Station-Id} cli %{Calling-Station-Id}
port %{NAS-Port} user %{User-Name}) -> Allocated IP: 192.168.0.1 from pool1
(did cli #ERX-40-b0-7a#E16#0 port 369098752 user user at mondomaine.fr)
Allocated IP: 192.168.0.1 from pool1 (did cli #ERX-40-b0-7a#E16#0 port
369098752 user user at mondomaine.fr)
++[sqlippool] returns ok
++[exec] returns noop
Sending Access-Accept of id 9 to 10.0.5.200 port 50000
NAS-IP-Address == 10.0.5.200
Framed-Protocol = PPP
Framed-Compression = Van-Jacobson-TCP-IP
Framed-IP-Address = 192.168.0.1
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
rad_recv: Accounting-Request packet from host 10.0.5.200 port 50016, id=85,
length=229
Acct-Status-Type = Start
User-Name = "user at mondomaine.fr"
Event-Timestamp = "Apr 27 2014 16:26:33 PDT"
Acct-Delay-Time = 0
NAS-Identifier = "ERX-40-b0-7a"
Acct-Session-Id = "erx FastEthernet 1/6:0012582922"
NAS-IP-Address = 10.0.5.200
Service-Type = Framed-User
Framed-Protocol = PPP
Framed-Compression = None
ERX-Pppoe-Description = "pppoe 00:1d:72:c6:7b:d5"
Framed-IP-Address = 192.168.0.1
Framed-IP-Netmask = 255.255.255.255
Calling-Station-Id = "#ERX-40-b0-7a#E16#0"
NAS-Port-Type = Ethernet
NAS-Port = 369098752
NAS-Port-Id = "FastEthernet 1/6"
Acct-Authentic = RADIUS
# Executing section preacct from file /etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 369098752,Client-IP-Address =
10.0.5.200,NAS-IP-Address = 10.0.5.200,Acct-Session-Id = "erx FastEthernet
1/6:0012582922",User-Name = "user at mondomaine.fr"'
[acct_unique] Acct-Unique-Session-ID = "b3e57c6c1b5cc9ca".
++[acct_unique] returns ok
[suffix] Looking up realm "mondomaine.fr" for User-Name = "
user at mondomaine.fr"
[suffix] No such realm "mondomaine.fr"
++[suffix] returns noop
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail] expand: %{Packet-Src-IP-Address} -> 10.0.5.200
[detail] expand:
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
-> /var/log/radius/radacct/10.0.5.200/detail-20140428
[detail]
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/radius/radacct/10.0.5.200/detail-20140428
[detail] expand: %t -> Mon Apr 28 00:56:37 2014
++[detail] returns ok
++[unix] returns ok
[radutmp] expand: /var/log/radius/radutmp -> /var/log/radius/radutmp
[radutmp] expand: %{User-Name} -> user at mondomaine.fr
++[radutmp] returns ok
rlm_sql (sql): Reserving sql socket id: 12
[sqlippool] expand: %{User-Name} -> user at mondomaine.fr
[sqlippool] sql_set_user escaped user --> 'user at mondomaine.fr'
[sqlippool] expand: START TRANSACTION -> START TRANSACTION
[sqlippool] expand: UPDATE radippool SET expiry_time = NOW() +
INTERVAL 3600 SECOND WHERE nasipaddress = '%{NAS-IP-Address}' AND
pool_key = '%{NAS-Port}' AND username = '%{User-Name}' AND
callingstationid = '%{Calling-Station-Id}' AND framedipaddress =
'%{Framed-IP-Address}' -> UPDATE radippool SET expiry_time = NOW() +
INTERVAL 3600 SECOND WHERE nasipaddress = '10.0.5.200' AND pool_key =
'369098752' AND username = 'user at mondomaine.fr' AND callingstationid =
'=23ERX-40-b0-7a=23E16=230' AND framedipaddress = '192.168.0.1'
[sqlippool] expand: COMMIT -> COMMIT
rlm_sql (sql): Released sql socket id: 12
++[sqlippool] returns ok
++[exec] returns noop
[attr_filter.accounting_response] expand: %{User-Name} ->
user at mondomaine.fr
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 85 to 10.0.5.200 port 50016
Finished request 1.
Cleaning up request 1 ID 85 with timestamp +6
Going to the next request
Waking up in 4.9 seconds.
Cleaning up request 0 ID 9 with timestamp +6
Ready to process requests.
rad_recv: Accounting-Request packet from host 10.0.5.200 port 50016, id=86,
length=301
Acct-Status-Type = Stop
User-Name = "user at mondomaine.fr"
Event-Timestamp = "Apr 27 2014 16:26:41 PDT"
Acct-Delay-Time = 0
NAS-Identifier = "ERX-40-b0-7a"
Acct-Session-Id = "erx FastEthernet 1/6:0012582922"
NAS-IP-Address = 10.0.5.200
Service-Type = Framed-User
Framed-Protocol = PPP
Framed-Compression = None
ERX-Pppoe-Description = "pppoe 00:1d:72:c6:7b:d5"
Framed-IP-Address = 192.168.0.1
Framed-IP-Netmask = 255.255.255.255
Calling-Station-Id = "#ERX-40-b0-7a#E16#0"
Acct-Input-Gigawords = 0
Acct-Input-Octets = 280
Acct-Output-Gigawords = 0
Acct-Output-Octets = 54
ERX-Input-Gigapkts = 0
Acct-Input-Packets = 0
ERX-Output-Gigapkts = 0
Acct-Output-Packets = 0
NAS-Port-Type = Ethernet
NAS-Port = 369098752
NAS-Port-Id = "FastEthernet 1/6"
Acct-Authentic = RADIUS
Acct-Session-Time = 8
Acct-Terminate-Cause = User-Request
# Executing section preacct from file /etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 369098752,Client-IP-Address =
10.0.5.200,NAS-IP-Address = 10.0.5.200,Acct-Session-Id = "erx FastEthernet
1/6:0012582922",User-Name = "user at mondomaine.fr"'
[acct_unique] Acct-Unique-Session-ID = "b3e57c6c1b5cc9ca".
++[acct_unique] returns ok
[suffix] Looking up realm "mondomaine.fr" for User-Name = "
user at mondomaine.fr"
[suffix] No such realm "mondomaine.fr"
++[suffix] returns noop
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail] expand: %{Packet-Src-IP-Address} -> 10.0.5.200
[detail] expand:
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
-> /var/log/radius/radacct/10.0.5.200/detail-20140428
[detail]
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/radius/radacct/10.0.5.200/detail-20140428
[detail] expand: %t -> Mon Apr 28 00:56:45 2014
++[detail] returns ok
++[unix] returns ok
[radutmp] expand: /var/log/radius/radutmp -> /var/log/radius/radutmp
[radutmp] expand: %{User-Name} -> user at mondomaine.fr
++[radutmp] returns ok
rlm_sql (sql): Reserving sql socket id: 11
[sqlippool] expand: %{User-Name} -> user at mondomaine.fr
[sqlippool] sql_set_user escaped user --> 'user at mondomaine.fr'
[sqlippool] expand: START TRANSACTION -> START TRANSACTION
[sqlippool] expand: UPDATE radippool SET nasipaddress = '', pool_key =
0, callingstationid = '', username = '', expiry_time = NULL WHERE
nasipaddress = '%{Nas-IP-Address}' AND pool_key = '%{NAS-Port}' AND
username = '%{User-Name}' AND callingstationid = '%{Calling-Station-Id}'
AND framedipaddress = '%{Framed-IP-Address}' -> UPDATE radippool SET
nasipaddress = '', pool_key = 0, callingstationid = '', username = '',
expiry_time = NULL WHERE nasipaddress = '10.0.5.200' AND pool_key =
'369098752' AND username = 'user at mondomaine.fr' AND callingstationid =
'=23ERX-40-b0-7a=23E16=230' AND framedipaddress = '192.168.0.1'
[sqlippool] expand: COMMIT -> COMMIT
[sqlippool] expand: Released IP %{Framed-IP-Address} (did
%{Called-Station-Id} cli %{Calling-Station-Id} user %{User-Name}) ->
Released IP 192.168.0.1 (did cli #ERX-40-b0-7a#E16#0 user
user at mondomaine.fr)
Released IP 192.168.0.1 (did cli #ERX-40-b0-7a#E16#0 user
user at mondomaine.fr)
rlm_sql (sql): Released sql socket id: 11
++[sqlippool] returns ok
++[exec] returns noop
[attr_filter.accounting_response] expand: %{User-Name} ->
user at mondomaine.fr
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 86 to 10.0.5.200 port 50016
Finished request 2.
Cleaning up request 2 ID 86 with timestamp +14
Going to the next request
Ready to process requests.
[root at localhost ~]#
-------------------------------------------------
Thanks
2014-04-28 18:43 GMT+09:00 yata <aurens.memuro02 at gmail.com>:
> Hi!
>
> I wanna freeradius2 as a dhcp-server
> When I connect to freeradius-server from laptop (Windows Vista) via ERX310
> by using PPPoE
> Following massages appeared.
> On the laptop I saw an error message "*Error 734: The PPP link control
> protocol was terminated."*
> What's wrong with my configuration?
> Please suggest to me what information should I provide you.
>
> ---------------------------raius.log----------------------------------
> Mon Apr 28 01:05:03 2014 : Info: ... adding new socket proxy address *
> port 36233
> Mon Apr 28 01:05:03 2014 : Info: Ready to process requests.
> Mon Apr 28 01:06:11 2014 : Auth: Login OK: [user at mondomaine.fr] (from
> client GGSN1 port 369098752 cli #ERX-40-b0-7a#E16#0)
> Mon Apr 28 01:06:11 2014 : Info: Allocated IP: 192.168.0.1 from pool1
> (did cli #ERX-40-b0-7a#E16#0 port 369098752 user user at mondomaine.fr)
> Mon Apr 28 01:06:18 2014 : Info: Released IP 192.168.0.1 (did cli
> #ERX-40-b0-7a#E16#0 user user at mondomaine.fr)
> Mon Apr 28 01:06:22 2014 : Info: Signalled to terminate
> Mon Apr 28 01:06:22 2014 : Info: Exiting normally.
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 14
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 13
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 12
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 11
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 10
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 9
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 8
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 7
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 6
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 5
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 4
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 3
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 2
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 1
> Mon Apr 28 01:06:22 2014 : Info: rlm_sql (sql): Closing sqlsocket 0
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Driver rlm_sql_mysql
> (module rlm_sql_mysql) loaded and linked
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect to
> userfreeradius at localhost:/freeradius
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #0
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #0
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle, #0
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #1
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #1
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle, #1
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #2
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #2
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle, #2
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #3
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #3
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle, #3
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #4
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #4
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle, #4
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #5
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #5
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle, #5
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #6
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #6
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle, #6
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #7
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #7
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle, #7
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #8
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #8
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle, #8
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #9
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #9
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle, #9
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #10
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #10
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle,
> #10
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #11
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #11
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle,
> #11
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #12
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #12
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle,
> #12
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #13
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #13
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle,
> #13
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Attempting to connect
> rlm_sql_mysql #14
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql_mysql: Starting connect to MySQL
> server for #14
> Mon Apr 28 01:06:25 2014 : Info: rlm_sql (sql): Connected new DB handle,
> #14
> Mon Apr 28 01:06:25 2014 : Info: Loaded virtual server <default>
> Mon Apr 28 01:06:25 2014 : Info: Loaded virtual server inner-tunnel
> Mon Apr 28 01:06:25 2014 : Info: ... adding new socket proxy address *
> port 47655
> Mon Apr 28 01:06:25 2014 : Info: Ready to process requests.
> ------------------------------------------
>
> Thanks.
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20140429/fab9835a/attachment-0001.html>
More information about the Freeradius-Users
mailing list