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