Re: freeradius and mikrotik auth problem pppoe error 691
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@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
Everything looks fine in IP addresses, but the problem is still the same.
No, it's not looking fine.
Mikrotik debug log
. has no trace of Access-Accept packet - it didn't arrive.
Here again the log of Mikrotik and freeradius:
Stop looking at the logs and start looking at the network. Ivan Kalik Kalik Informatika ISP
2009/3/19 Lazar Cherveniakov <lazkom@mail.bg>:
Everything looks fine in IP addresses, but the problem is still the same.
Looks like you got exactly the problem I described. See here :
Mikrotik debug log 01:33:40 radius,debug sending 53:02 to 192.168.200.2:1812
Mikrotik thinks radius IP is 192.168.200.2
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 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
... while that IP is secondary IP on the radius server. Do a tcpdump on radius and you should see that radius replies comes from 192.168.200.3 (which mikrotik discards, because it's not the IP it sends the request to). There are several ways to fix this (one of them involves recompiling freeradius with --with-udpfromto, see http://wiki.freeradius.org/index.php/FAQ#Why_does_the_NAS_ignore_the_RADIUS_... ), but the easiest way is simply change mikrotik's config to use 192.168.200.3 as radius IP address. Regards, Fajar
i had the same problem when i wanted to authenticate the hotspot`s user with freeradius. the solution was to make a static mapping on IP - HOTSPOT - IP BINDINGS MAC address : THE MAC OF THE SERVER ADDRESS : THE IP ADDRESS OF THE SERVER TO ADDRESS : THE SAME AS ABOVE SERVER : ALL TYPE : REGULAR or BYPASSED and than it worked. it was related since the hotspot connections are passed to the mikrotik`s webproxy ( capture portal/page ) 2009/3/19 Fajar A. Nugraha <fajar@fajar.net>
2009/3/19 Lazar Cherveniakov <lazkom@mail.bg>:
Everything looks fine in IP addresses, but the problem is still the same.
Looks like you got exactly the problem I described. See here :
Mikrotik debug log 01:33:40 radius,debug sending 53:02 to 192.168.200.2:1812
Mikrotik thinks radius IP is 192.168.200.2
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 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
... while that IP is secondary IP on the radius server. Do a tcpdump on radius and you should see that radius replies comes from 192.168.200.3 (which mikrotik discards, because it's not the IP it sends the request to).
There are several ways to fix this (one of them involves recompiling freeradius with --with-udpfromto, see
http://wiki.freeradius.org/index.php/FAQ#Why_does_the_NAS_ignore_the_RADIUS_... ), but the easiest way is simply change mikrotik's config to use 192.168.200.3 as radius IP address.
Regards,
Fajar
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
participants (4)
-
Fajar A. Nugraha -
Lazar Cherveniakov -
orion -
tnt＠kalik.net