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