freeradius and mikrotik auth problem pppoe error 691
Lazar Cherveniakov
lazkom at mail.bg
Thu Mar 19 12:03:16 CET 2009
Everything looks fine in IP addresses, but the problem is still the same.
Here again the log of Mikrotik and freeradius:
Mikrotik debug log
01:33:40 pppoe,info PPPoE connection established from 00:15:AF:1F:23:1A
01:33:40 pppoe,ppp,info <pppoe-0>: waiting for call...
01:33:40 radius,debug new request 53:02 code=Access-Request
service=ppp called-id=pppoe-in
01:33:40 radius,debug sending 53:02 to 192.168.200.2:1812
01:33:40 radius,debug,packet sending Access-Request with id 8 to
192.168.200.2:1812
01:33:40 radius,debug,packet Signature =
0x83d0415d6b98f0421df6bb83a01bdb28
01:33:40 radius,debug,packet Service-Type = 2
01:33:40 radius,debug,packet Framed-Protocol = 1
01:33:40 radius,debug,packet NAS-Port = 10
01:33:40 radius,debug,packet NAS-Port-Type = 15
01:33:40 radius,debug,packet User-Name = "lacho"
01:33:40 radius,debug,packet Calling-Station-Id = "00:15:AF:1F:23:1A"
01:33:40 radius,debug,packet Called-Station-Id = "pppoe-in"
01:33:40 radius,debug,packet NAS-Port-Id = "ether1"
01:33:40 radius,debug,packet CHAP-Challenge =
0xe3c819400560adadbf019f209dc42f7e
01:33:40 radius,debug,packet CHAP-Password =
0x01dad26d1d56167a1899b3e9c8a8ba01
01:33:40 radius,debug,packet 18
01:33:40 radius,debug,packet NAS-Identifier = "TEST-RADIUS"
01:33:40 radius,debug,packet NAS-IP-Address = 192.168.200.4
01:33:41 radius,debug resending 53:02
01:33:41 radius,debug,packet sending Access-Request with id 8 to
192.168.200.2:1812
01:33:41 radius,debug,packet Signature =
0x83d0415d6b98f0421df6bb83a01bdb28
01:33:41 radius,debug,packet Service-Type = 2
01:33:41 radius,debug,packet Framed-Protocol = 1
01:33:41 radius,debug,packet NAS-Port = 10
01:33:41 radius,debug,packet NAS-Port-Type = 15
01:33:41 radius,debug,packet User-Name = "lacho"
01:33:41 radius,debug,packet Calling-Station-Id = "00:15:AF:1F:23:1A"
01:33:41 radius,debug,packet Called-Station-Id = "pppoe-in"
01:33:41 radius,debug,packet NAS-Port-Id = "ether1"
01:33:41 radius,debug,packet CHAP-Challenge =
0xe3c819400560adadbf019f209dc42f7e
01:33:41 radius,debug,packet CHAP-Password =
0x01dad26d1d56167a1899b3e9c8a8ba01
01:33:41 radius,debug,packet 18
01:33:41 radius,debug,packet NAS-Identifier = "TEST-RADIUS"
01:33:41 radius,debug,packet NAS-IP-Address = 192.168.200.4
01:33:41 radius,debug resending 53:02
01:33:41 radius,debug,packet sending Access-Request with id 8 to
192.168.200.2:1812
01:33:41 radius,debug,packet Signature =
0x83d0415d6b98f0421df6bb83a01bdb28
01:33:41 radius,debug,packet Service-Type = 2
01:33:41 radius,debug,packet Framed-Protocol = 1
01:33:41 radius,debug,packet NAS-Port = 10
01:33:41 radius,debug,packet NAS-Port-Type = 15
01:33:41 radius,debug,packet User-Name = "lacho"
01:33:41 radius,debug,packet Calling-Station-Id = "00:15:AF:1F:23:1A"
01:33:41 radius,debug,packet Called-Station-Id = "pppoe-in"
01:33:41 radius,debug,packet NAS-Port-Id = "ether1" 01:33:41
radius,debug,packet CHAP-Challenge =
0xe3c819400560adadbf019f209dc42f7e 01:33:41 radius,debug,packet
CHAP-Password = 0x01dad26d1d56167a1899b3e9c8a8ba01 01:33:41
radius,debug,packet 18 01:33:41 radius,debug,packet
NAS-Identifier = "TEST-RADIUS" 01:33:41 radius,debug,packet
NAS-IP-Address = 192.168.200.4 01:33:41 radius,debug timeout for
53:02 01:33:41 pppoe,ppp,info <pppoe-lacho>: terminating... - user
lacho authentication failed - radius timeout (6) 01:33:41
pppoe,ppp,info <pppoe-lacho>: disconnected
Freeradius debug log:
Sending Access-Accept of id 7 to 192.168.200.4 port 32768
Acct-Interim-Interval = 300 Session-Timeout = 31
Mikrotik-Xmit-Limit = 1073217536 Framed-IP-Address =
10.8.15.44 Mikrotik-Recv-Limit = 1073217536
Framed-IP-Netmask = 255.255.255.255 Thu Mar 19 12:37:16 2009 : Debug:
Finished request 3 Thu Mar 19 12:37:16 2009 : Debug: Going to the next
request Thu Mar 19 12:37:16 2009 : Debug: Thread 4 waiting to be
assigned a request rad_recv: Access-Request packet from host
192.168.200.4:32768, id=8, length=144 Thu Mar 19 12:37:31 2009 :
Debug: --- Walking the entire request list --- Thu Mar 19 12:37:31
2009 : Debug: Cleaning up request 3 ID 7 with timestamp 49c2205c Thu
Mar 19 12:37:31 2009 : Debug: Waking up in 31 seconds... Thu Mar 19
12:37:31 2009 : Debug: Threads: total/active/spare threads = 5/0/5 Thu
Mar 19 12:37:31 2009 : Debug: Thread 5 got semaphore Thu Mar 19
12:37:31 2009 : Debug: Thread 5 handling request 4, (1 handled so far)
Service-Type = Framed-User Framed-Protocol = PPP
NAS-Port = 10 NAS-Port-Type = Ethernet User-Name =
"lacho" Calling-Station-Id = "00:15:AF:1F:23:1A"
Called-Station-Id = "pppoe-in" NAS-Port-Id = "ether1"
CHAP-Challenge = 0xe3c819400560adadbf019f209dc42f7e
CHAP-Password = 0x01dad26d1d56167a1899b3e9c8a8ba0118
NAS-Identifier = "TEST-RADIUS" NAS-IP-Address = 192.168.200.4
Thu Mar 19 12:37:31 2009 : Debug: Processing the authorize section
of radiusd.conf Thu Mar 19 12:37:31 2009 : Debug: modcall: entering
group authorize for request 4 Thu Mar 19 12:37:31 2009 : Debug:
modsingle[authorize]: calling preprocess (rlm_preprocess) for request
4 Thu Mar 19 12:37:31 2009 : Debug: modsingle[authorize]: returned
from preprocess (rlm_preprocess) for request 4 Thu Mar 19 12:37:31
2009 : Debug: modcall[authorize]: module "preprocess" returns ok for
request 4 Thu Mar 19 12:37:31 2009 : Debug: modsingle[authorize]:
calling pre_auth (rlm_exec) for request 4 Thu Mar 19 12:37:31 2009 :
Debug: Exec-Program output: Auth-Type := Accept Thu Mar 19 12:37:31
2009 : Debug: Exec-Program-Wait: value-pairs: Auth-Type := Accept
rad_recv: Access-Request packet from host 192.168.200.4:32768, id=8,
length=144 Thu Mar 19 12:37:31 2009 : Error: Discarding duplicate
request from client TEST-RADIUS:32768 - ID: 8 due to unfinished
request 4 Thu Mar 19 12:37:31 2009 : Debug: rl_next: returning NULL
Thu Mar 19 12:37:31 2009 : Debug: Waking up in 31 seconds... Thu Mar
19 12:37:31 2009 : Debug: Threads: total/active/spare threads = 5/1/4
Thu Mar 19 12:37:32 2009 : Debug: Exec-Program: returned: 0 Thu Mar 19
12:37:32 2009 : Debug: modsingle[authorize]: returned from pre_auth
(rlm_exec) for request 4 Thu Mar 19 12:37:32 2009 : Debug:
modcall[authorize]: module "pre_auth" returns ok for request 4 Thu Mar
19 12:37:32 2009 : Debug: modsingle[authorize]: calling mschap
(rlm_mschap) for request 4 Thu Mar 19 12:37:32 2009 : Debug:
modsingle[authorize]: returned from mschap (rlm_mschap) for request 4
Thu Mar 19 12:37:32 2009 : Debug: modcall[authorize]: module
"mschap" returns noop for request 4 Thu Mar 19 12:37:32 2009 : Debug:
modsingle[authorize]: calling files (rlm_files) for request 4 Thu
Mar 19 12:37:32 2009 : Debug: users: Matched entry DEFAULT at line
52 Thu Mar 19 12:37:32 2009 : Debug: modsingle[authorize]: returned
from files (rlm_files) for request 4 Thu Mar 19 12:37:32 2009 : Debug:
modcall[authorize]: module "files" returns ok for request 4 Thu Mar
19 12:37:32 2009 : Debug: modcall: leaving group authorize (returns
ok) for request 4 Thu Mar 19 12:37:32 2009 : Debug:
rad_check_password: Found Auth-Type Accept Thu Mar 19 12:37:32 2009 :
Debug: rad_check_password: Auth-Type = Accept, accepting the user
Thu Mar 19 12:37:32 2009 : Debug: Exec-Program output:
Acct-Interim-Interval = 300, Session-Timeout = 31, Mikrotik-Xmit-Limit
= 1073217536, Framed-IP-Address = 10.8.15.38, Mikrotik-Recv-Limit =
1073217536, Framed-IP-Netmask = 255.255.255.255, Thu Mar 19 12:37:32
2009 : Debug: Exec-Program-Wait: value-pairs: Acct-Interim-Interval =
300, Session-Timeout = 31, Mikrotik-Xmit-Limit = 1073217536,
Framed-IP-Address = 10.8.15.38, Mikrotik-Recv-Limit = 1073217536,
Framed-IP-Netmask = 255.255.255.255, rad_recv: Access-Request packet
from host 192.168.200.4:32768, id=8, length=144 Thu Mar 19 12:37:32
2009 : Error: Discarding duplicate request from client
TEST-RADIUS:32768 - ID: 8 due to unfinished request 4 Thu Mar 19
12:37:32 2009 : Debug: --- Walking the entire request list --- Thu Mar
19 12:37:32 2009 : Debug: Waking up in 5 seconds... Thu Mar 19
12:37:32 2009 : Debug: Exec-Program: returned: 0 Sending Access-Accept
of id 8 to 192.168.200.4 port 32768 Acct-Interim-Interval =
300 Session-Timeout = 31 Mikrotik-Xmit-Limit =
1073217536 Framed-IP-Address = 10.8.15.38
Mikrotik-Recv-Limit = 1073217536 Framed-IP-Netmask =
255.255.255.255 Thu Mar 19 12:37:32 2009 : Debug: Finished request 4
Thu Mar 19 12:37:32 2009 : Debug: Going to the next request Thu Mar 19
12:37:32 2009 : Debug: Thread 5 waiting to be assigned a request Thu
Mar 19 12:37:37 2009 : Debug: --- Walking the entire request list ---
Thu Mar 19 12:37:37 2009 : Debug: Cleaning up request 4 ID 8 with
timestamp 49c2206b Thu Mar 19 12:37:37 2009 : Debug: Nothing to do.
Sleeping until we see a request. Thu Mar 19 12:37:37 2009 : Debug:
Threads: total/active/spare threads = 5/0/5
mikrotik ip [admin at TEST-RADIUS] > ip address print Flags: X -
disabled, I - invalid, D - dynamic # ADDRESS NETWORK
BROADCAST INTERFACE 0 192.168.200.4/24 192.168.200.0
192.168.200.255 ether1
radius server ip`s
# ifconfig eth0 Link encap:Ethernet HWaddr 00:19:66:4E:F4:E8
inet addr:192.168.200.3 Bcast:192.168.200.255
Mask:255.255.255.0 inet6 addr: fe80::219:66ff:fe4e:f4e8/64
Scope:Link UP BROADCAST RUNNING MULTICAST MTU:1500
Metric:1 RX packets:67047606 errors:2 dropped:0 overruns:0
frame:0 TX packets:1327141 errors:0 dropped:0 overruns:0
carrier:0 collisions:0 txqueuelen:1000 RX
bytes:480659514 (458.3 MiB) TX bytes:570459851 (544.0 MiB)
Interrupt:17
eth0:1 Link encap:Ethernet HWaddr 00:19:66:4E:F4:E8
inet addr:192.168.200.2 Bcast:192.168.200.255 Mask:255.255.255.0
UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
Interrupt:17
eth0:3 Link encap:Ethernet HWaddr 00:19:66:4E:F4:E8
inet addr:212.70.XX.XX Bcast:212.XX.XX.255 Mask:255.255.255.0
UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1
Interrupt:17
lo Link encap:Local Loopback inet addr:127.0.0.1
Mask:255.0.0.0 inet6 addr: ::1/128 Scope:Host UP
LOOPBACK RUNNING MTU:16436 Metric:1 RX packets:37293
errors:0 dropped:0 overruns:0 frame:0 TX packets:37293
errors:0 dropped:0 overruns:0 carrier:0 collisions:0
txqueuelen:0 RX bytes:1787220 (1.7 MiB) TX bytes:1787220
(1.7 MiB)
And watch as I can not understand where is the problem?
Radius everything looks okay
More ideas?
Thank you
P.S. witout firewall
# iptables -L -v Chain INPUT (policy ACCEPT 0 packets, 0 bytes)
pkts bytes target prot opt in out source
destination
Chain FORWARD (policy ACCEPT 0 packets, 0 bytes) pkts bytes target
prot opt in out source destination
Chain OUTPUT (policy ACCEPT 0 packets, 0 bytes) pkts bytes target
prot opt in out source destination
Thanks
--
Lazar Cherveniakov
Micro computers system - Lazkom
LIVE FREE OR DIE
-------------------------------------
Powered by Mail.BG - http://mail.bg
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20090319/b6dee217/attachment.html>
More information about the Freeradius-Users
mailing list