FreeRadius error

Hammy · May 26, 2006, 8:57pm

When I tell NTradPing to authenticate to my free radius server, I get:

rad_recv: Access-Request packet from host 10.1.5.10:3549, id=2, length=50
        User-Name = "testing123"
        Password = "blah123"
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
rlm_sql (sql): Processing sql_postauth
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql (sql): Released sql socket id: 3
Sending Access-Accept of id 2 to 10.1.5.10 port 3549
        Framed-IP-Address = 192.168.0.100

When I use my Mikrotik, I get:

rad_recv: Access-Request packet from host 10.1.10.100:42351, id=20, length=205
        Service-Type = Framed
        Framed-Protocol = PPP
        NAS-Port = 135
        NAS-Port-Type = Ethernet
        User-Name = "testing123"
        Calling-Station-Id = "00:15:6D:10:0A:FD"
        Called-Station-Id = "ICS - North"
        NAS-Port-Id = "North"
        MS-CHAP-Challenge = "\010J\253LnE\037"\032j\321B%\0038Y"
        MS-CHAP2-Response = "\001\000\235\331.N\005\002\362\3744\232\356\216\213orN\000\000\000\000\000\000\000\000mi\225M\205~nS6\244\203\2520\312\213\226\014\325\013\346\223dy\255"
        NAS-Identifier = "ICSAP1-HammettFarms1"
        NAS-IP-Address = 10.1.10.100
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
No memory
rlm_sql (sql): Processing sql_postauth
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql (sql): Released sql socket id: 3
Sending Access-Accept of id 20 to 10.1.10.100 port 42351
        Framed-IP-Address = 192.168.0.100
        MS-CHAP2-Success = "\001S=9C1C8DACBA3127C43B238E7E82A31DF3799B6BBC"
rad_recv: Access-Request packet from host 10.1.10.100:42351, id=20, length=205
Re-sending Access-Accept of id 20 to 10.1.10.100 port 42351
rad_recv: Access-Request packet from host 10.1.10.100:42351, id=20, length=205
Re-sending Access-Accept of id 20 to 10.1.10.100 port 42351
rad_recv: Access-Request packet from host 10.1.10.100:42351, id=21, length=205
        Service-Type = Framed
        Framed-Protocol = PPP
        NAS-Port = 136
        NAS-Port-Type = Ethernet
        User-Name = "testing123"
        Calling-Station-Id = "00:15:6D:10:0A:FD"
        Called-Station-Id = "ICS - North"
        NAS-Port-Id = "North"
        MS-CHAP-Challenge = "\302k\257\206T$_\275\272\272,\215\256\335\216W"
        MS-CHAP2-Response = "\001\00037\0145\222\351i\246Z\225c\010H\027q\354\000\000\000\000\000\000\000\000(w\227\276\200\030\350*\017\355\267B\003|\337\207mRT8\233ER\366"
        NAS-Identifier = "ICSAP1-HammettFarms1"
        NAS-IP-Address = 10.1.10.100
rlm_sql (sql): Reserving sql socket id: 2
rlm_sql (sql): Released sql socket id: 2
No memory
rlm_sql (sql): Processing sql_postauth
rlm_sql (sql): Reserving sql socket id: 1
rlm_sql (sql): Released sql socket id: 1
Sending Access-Accept of id 21 to 10.1.10.100 port 42351
        Framed-IP-Address = 192.168.0.100
        MS-CHAP2-Success = "\001S=1F351F4AD95D7DECFBC82677394AFC19CA31B27C"
rad_recv: Access-Request packet from host 10.1.10.100:42351, id=21, length=205
Re-sending Access-Accept of id 21 to 10.1.10.100 port 42351
rad_recv: Access-Request packet from host 10.1.10.100:42351, id=21, length=205
Re-sending Access-Accept of id 21 to 10.1.10.100 port 42351
rad_recv: Access-Request packet from host 10.1.10.100:42351, id=22, length=205
        Service-Type = Framed
        Framed-Protocol = PPP
        NAS-Port = 137
        NAS-Port-Type = Ethernet
        User-Name = "testing123"
        Calling-Station-Id = "00:15:6D:10:0A:FD"
        Called-Station-Id = "ICS - North"
        NAS-Port-Id = "North"
        MS-CHAP-Challenge = "\210\365\353\277\257U[\264\250e\003h\2527\026\235"
        MS-CHAP2-Response = "\001\000\352\232\333\003\257\327!\017\003c\334\003\353\342\250\247\000\000\000\000\000\000\000\000\001\371\313\335\354\321l#g4\025\210Nf\316\234\271\377\220\236\237\370\255]"
        NAS-Identifier = "ICSAP1-HammettFarms1"
        NAS-IP-Address = 10.1.10.100
rlm_sql (sql): Reserving sql socket id: 0
rlm_sql (sql): Released sql socket id: 0
No memory
rlm_sql (sql): Processing sql_postauth
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
Sending Access-Accept of id 22 to 10.1.10.100 port 42351
        Framed-IP-Address = 192.168.0.100
        MS-CHAP2-Success = "\001S=5CAEFF7DA325F6C17DEB155F56DA88B0D9F80664"
rad_recv: Access-Request packet from host 10.1.10.100:42351, id=22, length=205
Re-sending Access-Accept of id 22 to 10.1.10.100 port 42351
rad_recv: Access-Request packet from host 10.1.10.100:42351, id=22, length=205
Re-sending Access-Accept of id 22 to 10.1.10.100 port 42351

okay, so maybe I’m low on memory.

[root@radius mhammett]# free -m
             total       used       free     shared    buffers     cached
Mem:           311         97        214          0          9         46
-/+ buffers/cache:         41        270
Swap:          927          0        927

Nope, I have plenty of memory. Ideas?

Hammy · May 26, 2006, 9:24pm

From the MT log:

15:22:42 pppoe,info PPPoE connection established from 00:15:6D:10:0A:FD
15:22:42 pppoe,ppp,info <pppoe-0>: waiting for call...
15:22:43 pppoe,ppp,info <pppoe-testing123>: terminating... - user testing123 authentication failed - radius timeout (6)
15:22:43 pppoe,ppp,info <pppoe-testing123>: disconnected

savage · May 29, 2006, 6:06am

There are no timestamps in that log - but it looks to me by the amount of retransmissions that MT is not waiting long enough for a reply from the radius server…

Increase your Radius Timeout value in MT to something sensable… See if that shed some light on the issue. Your radius is working fine (it did send a access-accept), MT just didn’t wait long enough for it.

–
C

jager · May 29, 2006, 11:57pm

I agree. We had very similar problems, so I get mad and set radius timeout to 10000 … now everything is running fine

Hammy · May 30, 2006, 7:59pm

I had it set for 5000, I tried 10000 and 50000. It connects for a while, but then will drop and reconnect.

savage · May 30, 2006, 8:04pm

Based on your debug log and the contents of the Access-Accept, I’d say as logn as it connects your problem is not the Radius.

Something else is causing the disconnects.

Hammy · May 30, 2006, 8:48pm

With the time out set to 50000 ms, at about 30 seconds something causes it to attempt again.

After the radius server says it sent the IP address, the PPPoE client says it is still authenticating.

Ready to process requests.
rad_recv: Access-Request packet from host 10.1.10.100:32886, id=14, length=160
        Service-Type = Framed
        Framed-Protocol = PPP
        NAS-Port = 120
        NAS-Port-Type = Ethernet
        User-Name = "testing123"
        Calling-Station-Id = "00:0B:6B:35:AE:C1"
        Called-Station-Id = "ICS - South"
        NAS-Port-Id = "South"
        CHAP-Challenge = "37\0145\222\351i\246Z\225c\010H\027q\354"
        CHAP-Password = "\001${*6\246\346\345Z\026\321Dr^k\035\332"
        NAS-Identifier = "ICSAP1-HammettFarms1"
        NAS-IP-Address = 10.1.10.100
  rlm_chap: Setting 'Auth-Type := CHAP'
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
  rlm_chap: login attempt by "testing123" with CHAP password
  rlm_chap: Using clear text password blah123 for user testing123 authentication.
  rlm_chap: chap user testing123 authenticated succesfully
rlm_sql (sql): Processing sql_postauth
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql (sql): Released sql socket id: 3
Sending Access-Accept of id 14 to 10.1.10.100 port 32886
        Framed-IP-Address = 192.168.0.100
rad_recv: Access-Request packet from host 10.1.10.100:32887, id=15, length=160
        Service-Type = Framed
        Framed-Protocol = PPP
        NAS-Port = 121
        NAS-Port-Type = Ethernet
        User-Name = "testing123"
        Calling-Station-Id = "00:0B:6B:35:AE:C1"
        Called-Station-Id = "ICS - South"
        NAS-Port-Id = "South"
        CHAP-Challenge = "\352\232\333\003\257\327!\017\003c\334\003\353\342\250\247"
        CHAP-Password = "\001E\241\364oCXZ\303\317\313\327\364\031\324\245R"
        NAS-Identifier = "ICSAP1-HammettFarms1"
        NAS-IP-Address = 10.1.10.100
  rlm_chap: Setting 'Auth-Type := CHAP'
rlm_sql (sql): Reserving sql socket id: 2
rlm_sql (sql): Released sql socket id: 2
  rlm_chap: login attempt by "testing123" with CHAP password
  rlm_chap: Using clear text password blah123 for user testing123 authentication.
  rlm_chap: chap user testing123 authenticated succesfully
rlm_sql (sql): Processing sql_postauth
rlm_sql (sql): Reserving sql socket id: 1
rlm_sql (sql): Released sql socket id: 1
Sending Access-Accept of id 15 to 10.1.10.100 port 32887
        Framed-IP-Address = 192.168.0.100

15:41:06 pppoe,info PPPoE connection established from 00:0B:6B:35:AE:C1 
15:41:06 pppoe,ppp,info <pppoe-0>: waiting for call... 
15:41:36 pppoe,info PPPoE connection established from 00:0B:6B:35:AE:C1 
15:41:36 pppoe,info PPPoE connection from 00:0B:6B:35:AE:C1 was already active - closing 
    previous one 
15:41:36 pppoe,ppp,info <pppoe-testing123>: terminating... - disconnected 
15:41:36 pppoe,ppp,info <pppoe-testing123>: disconnected 
15:41:36 pppoe,ppp,info <pppoe-0>: waiting for call... 
15:41:41 pppoe,ppp,info <pppoe-testing123>: terminating... 
15:41:41 pppoe,ppp,info <pppoe-testing123>: disconnected

At this point I disabled the client. Then this came through a good 5 - 10 seconds later.

rad_recv: Access-Request packet from host 10.1.10.100:32886, id=14, length=160
        Service-Type = Framed
        Framed-Protocol = PPP
        NAS-Port = 120
        NAS-Port-Type = Ethernet
        User-Name = "testing123"
        Calling-Station-Id = "00:0B:6B:35:AE:C1"
        Called-Station-Id = "ICS - South"
        NAS-Port-Id = "South"
        CHAP-Challenge = "37\0145\222\351i\246Z\225c\010H\027q\354"
        CHAP-Password = "\001${*6\246\346\345Z\026\321Dr^k\035\332"
        NAS-Identifier = "ICSAP1-HammettFarms1"
        NAS-IP-Address = 10.1.10.100
  rlm_chap: Setting 'Auth-Type := CHAP'
rlm_sql (sql): Reserving sql socket id: 0
rlm_sql (sql): Released sql socket id: 0
  rlm_chap: login attempt by "testing123" with CHAP password
  rlm_chap: Using clear text password blah123 for user testing123 authentication.
  rlm_chap: chap user testing123 authenticated succesfully
rlm_sql (sql): Processing sql_postauth
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
Sending Access-Accept of id 14 to 10.1.10.100 port 32886
        Framed-IP-Address = 192.168.0.100
rad_recv: Access-Request packet from host 10.1.10.100:32887, id=15, length=160
        Service-Type = Framed
        Framed-Protocol = PPP
        NAS-Port = 121
        NAS-Port-Type = Ethernet
        User-Name = "testing123"
        Calling-Station-Id = "00:0B:6B:35:AE:C1"
        Called-Station-Id = "ICS - South"
        NAS-Port-Id = "South"
        CHAP-Challenge = "\352\232\333\003\257\327!\017\003c\334\003\353\342\250\247"
        CHAP-Password = "\001E\241\364oCXZ\303\317\313\327\364\031\324\245R"
        NAS-Identifier = "ICSAP1-HammettFarms1"
        NAS-IP-Address = 10.1.10.100
  rlm_chap: Setting 'Auth-Type := CHAP'
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql (sql): Released sql socket id: 3
  rlm_chap: login attempt by "testing123" with CHAP password
  rlm_chap: Using clear text password blah123 for user testing123 authentication.
  rlm_chap: chap user testing123 authenticated succesfully
rlm_sql (sql): Processing sql_postauth
rlm_sql (sql): Reserving sql socket id: 2
rlm_sql (sql): Released sql socket id: 2
Sending Access-Accept of id 15 to 10.1.10.100 port 32887
        Framed-IP-Address = 192.168.0.100
rad_recv: Access-Request packet from host 10.1.10.100:32886, id=14, length=160
        Service-Type = Framed
        Framed-Protocol = PPP
        NAS-Port = 120
        NAS-Port-Type = Ethernet
        User-Name = "testing123"
        Calling-Station-Id = "00:0B:6B:35:AE:C1"
        Called-Station-Id = "ICS - South"
        NAS-Port-Id = "South"
        CHAP-Challenge = "37\0145\222\351i\246Z\225c\010H\027q\354"
        CHAP-Password = "\001${*6\246\346\345Z\026\321Dr^k\035\332"
        NAS-Identifier = "ICSAP1-HammettFarms1"
        NAS-IP-Address = 10.1.10.100
  rlm_chap: Setting 'Auth-Type := CHAP'
rlm_sql (sql): Reserving sql socket id: 1
rlm_sql (sql): Released sql socket id: 1
  rlm_chap: login attempt by "testing123" with CHAP password
  rlm_chap: Using clear text password blah123 for user testing123 authentication.
  rlm_chap: chap user testing123 authenticated succesfully
rlm_sql (sql): Processing sql_postauth
rlm_sql (sql): Reserving sql socket id: 0
rlm_sql (sql): Released sql socket id: 0
Sending Access-Accept of id 14 to 10.1.10.100 port 32886
        Framed-IP-Address = 192.168.0.100
rad_recv: Access-Request packet from host 10.1.10.100:32887, id=15, length=160
        Service-Type = Framed
        Framed-Protocol = PPP
        NAS-Port = 121
        NAS-Port-Type = Ethernet
        User-Name = "testing123"
        Calling-Station-Id = "00:0B:6B:35:AE:C1"
        Called-Station-Id = "ICS - South"
        NAS-Port-Id = "South"
        CHAP-Challenge = "\352\232\333\003\257\327!\017\003c\334\003\353\342\250\247"
        CHAP-Password = "\001E\241\364oCXZ\303\317\313\327\364\031\324\245R"
        NAS-Identifier = "ICSAP1-HammettFarms1"
        NAS-IP-Address = 10.1.10.100
  rlm_chap: Setting 'Auth-Type := CHAP'
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Released sql socket id: 4
  rlm_chap: login attempt by "testing123" with CHAP password
  rlm_chap: Using clear text password blah123 for user testing123 authentication.
  rlm_chap: chap user testing123 authenticated succesfully
rlm_sql (sql): Processing sql_postauth
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql (sql): Released sql socket id: 3
Sending Access-Accept of id 15 to 10.1.10.100 port 32887
        Framed-IP-Address = 192.168.0.100

I double checked and the client IS indeed disabled.

I have the radius server off one sector of an AP running N-Streme. I’ve tried the PPPoE client from both the CPE that is between the radius and the AP as well as a CPE on a different sector. Same thing.

savage · May 30, 2006, 9:01pm

Hmmm…

The second transmission is normal. You have a timeout value that you can set, and a retransmission interval which is not yet configurable. Retransmissions will occur if the radius server takes to long to respond.

This is going to be a difficult road for you unfortunately. Radius uses UDP - which is unlike TCP, a stateless protocol. It simply fires off a packet and does not care whether the packet makes it to the destination in once piece…

Do you have congested / slow / high latency links between the AP and the Radius server? What kind of ping replies do you get between the AP and the radius server? Any packet loss (extremely important that you don’t) I’m starting to think that you perhaps are suffering from packet loss here - UDP will be the first kind of packets to be dropped on a congested link due to it’s connection-less state.

I presume on the CPE, you eventually just get a authentication error, right?

–
C

Hammy · May 30, 2006, 9:41pm

There is minimal traffic going over the link.

— 10.1.10.100 ping statistics —
1000 packets transmitted, 992 received, 0% packet loss, time 999704ms
rtt min/avg/max/mdev = 1.992/14.969/98.004/15.758 ms, pipe 2

Wireless performance on AP

[admin@ICSAP1-HammettFarms1] > /interface wireless monitor North once
                 status: running-ap
                   band: 5ghz
              frequency: 5785MHz
            noise-floor: -105dBm
         overall-tx-ccq: 55%
     registered-clients: 1
  authenticated-clients: 1
                nstreme: yes
                polling: yes
      current-tx-powers: 6Mbps:19,9Mbps:19,12Mbps:19,18Mbps:19,24Mbps:19,36Mbps:15,48Mbps:14,54Mbps:13
    notify-external-fdb: no

Wireless performance on radius CPE

[admin@Seco] > /interface wireless monitor wlan1 once 
               status: connected-to-ess
                 band: 5ghz
            frequency: 5785MHz
              tx-rate: 12Mbps
              rx-rate: 24Mbps
                 ssid: "ICS1"
                bssid: 00:15:6D:10:0A:F9
           radio-name: "00156D100AF9"
      signal-strength: -81dBm
   tx-signal-strength: -78dBm
          noise-floor: -104dBm
      signal-to-noise: 23dB
               tx-ccq: 32%
               rx-ccq: 58%
         p-throughput: 18151
             wds-link: no
              nstreme: yes
              polling: yes
         framing-mode: none
     routeros-version: "2.9.23"
              last-ip: 64.12.161.185
  802.1x-port-enabled: yes
  authentication-type: none
           encryption: none
          compression: no
    current-tx-powers: 6Mbps:19,9Mbps:19,12Mbps:19,18Mbps:19,24Mbps:19,36Mbps:15,48Mbps:14,
                       54Mbps:13
  notify-external-fdb: no

Wireless settings on AP

[admin@ICSAP1-HammettFarms1] > /interface wireless print 
Flags: X - disabled, R - running 
 0  R name="North" mtu=1500 mac-address=00:15:6D:10:0A:F9 arp=enabled disable-running-check=no interface-type=Atheros AR5213 
      radio-name="00156D100AF9" mode=ap-bridge ssid="ICS1" area="" frequency-mode=manual-txpower country=no_country_set antenna-gain=0 
      frequency=5785 band=5ghz scan-list=default rate-set=default supported-rates-a/g=6Mbps,9Mbps,12Mbps,18Mbps,24Mbps,36Mbps,48Mbps,54Mbps 
      basic-rates-a/g=6Mbps max-station-count=2007 ack-timeout=121 tx-power-mode=default noise-floor-threshold=default 
      periodic-calibration=enabled periodic-calibration-interval=60 burst-time=disabled dfs-mode=none antenna-mode=ant-a wds-mode=disabled 
      wds-default-bridge=none wds-default-cost=100 wds-cost-range=50-150 wds-ignore-ssid=no update-stats-interval=disabled 
      default-authentication=yes default-forwarding=yes default-ap-tx-limit=0 default-client-tx-limit=0 hide-ssid=no security-profile=default 
      disconnect-timeout=3s on-fail-retry-time=100ms preamble-mode=short compression=no allow-sharedkey=no 

 1  R name="South" mtu=1500 mac-address=00:15:6D:10:0A:FA arp=enabled disable-running-check=no interface-type=Atheros AR5213 
      radio-name="00156D100AFA" mode=ap-bridge ssid="ICS2" area="" frequency-mode=manual-txpower country=no_country_set antenna-gain=0 
      frequency=5810 band=5ghz-10mhz scan-list=5810 rate-set=default supported-rates-a/g=6Mbps,9Mbps,12Mbps,18Mbps,24Mbps,36Mbps,48Mbps,54Mbps 
      basic-rates-a/g=6Mbps max-station-count=2007 ack-timeout=121 tx-power-mode=default noise-floor-threshold=default 
      periodic-calibration=enabled periodic-calibration-interval=60 burst-time=disabled dfs-mode=none antenna-mode=ant-a wds-mode=disabled 
      wds-default-bridge=none wds-default-cost=100 wds-cost-range=50-150 wds-ignore-ssid=no update-stats-interval=disabled 
      default-authentication=yes default-forwarding=yes default-ap-tx-limit=0 default-client-tx-limit=0 hide-ssid=no security-profile=default 
      disconnect-timeout=3s on-fail-retry-time=100ms preamble-mode=short compression=no allow-sharedkey=no

Wireless settings on CPE near Radius server

[admin@Seco] > /interface wireless print 
Flags: X - disabled, R - running 
 0  R name="wlan1" mtu=1500 mac-address=00:15:6D:10:0A:FD arp=enabled disable-running-check=no 
      interface-type=Atheros AR5213 radio-name="00156D100AFD" mode=station ssid="ICS1" area="" 
      frequency-mode=manual-txpower country=no_country_set antenna-gain=0 frequency=5785 
      band=5ghz scan-list=default rate-set=default 
      supported-rates-a/g=6Mbps,9Mbps,12Mbps,18Mbps,24Mbps,36Mbps,48Mbps,54Mbps 
      basic-rates-a/g=6Mbps max-station-count=2007 ack-timeout=121 tx-power-mode=default 
      noise-floor-threshold=default periodic-calibration=default 
      periodic-calibration-interval=60 burst-time=disabled dfs-mode=none antenna-mode=ant-a 
      wds-mode=disabled wds-default-bridge=none wds-default-cost=100 wds-cost-range=50-150 
      wds-ignore-ssid=no update-stats-interval=disabled default-authentication=yes 
      default-forwarding=yes default-ap-tx-limit=0 default-client-tx-limit=0 hide-ssid=no 
      security-profile=default disconnect-timeout=3s on-fail-retry-time=100ms 
      preamble-mode=both compression=yes allow-sharedkey=no

Hammy · May 30, 2006, 9:46pm

oops, I forgot to answer your last question.

After noticing I had not set the time zone\dst\ntp settings properly, I noticed this on the CPE:

20:41:06 pppoe,ppp,info Radius Test: initializing... 
20:41:06 pppoe,ppp,info Radius Test: dialing... 
20:41:06 system,info device changed by admin 
20:41:36 pppoe,ppp,info Radius Test: terminating... - failed to authenticate 
20:41:36 pppoe,ppp,info Radius Test: disconnected 
20:41:36 pppoe,ppp,info Radius Test: initializing... 
20:41:36 pppoe,ppp,info Radius Test: dialing... 
20:41:40 pppoe,ppp,info Radius Test: terminating... - administrator request 
20:41:40 pppoe,ppp,info Radius Test: disabled 
20:41:40 system,info device changed by admin

savage · May 31, 2006, 6:08am

Hmm,

I must admit, I’m at a bit of loss for words here. It’s obvious that the reply from the radius server is not received in a timely manner by the mikrotik. The debug info on the radius server is correct, I can’t see anything wrong with that. It’s simply a matter of getting the packets to the Mikrotik in a timely manner…

Try this

/system logging add topics=radius,debug action=echo

Let’s see what mikrotik says… We might get a bit wiser out of that, but I doubt we can solve this issue unless there are comms problems between the two systems that we can resolve.

Hammy · May 31, 2006, 6:04pm

[admin@ICSAP1-HammettFarms1] > 
  (5 messages discarded)
echo: radius,debug,packet     Framed-Protocol = 1
echo: radius,debug,packet     NAS-Port = 123
echo: radius,debug,packet     NAS-Port-Type = 15
echo: radius,debug,packet     User-Name = "testing123"
echo: radius,debug,packet     Calling-Station-Id = "00:0B:6B:35:AE:C1"
echo: radius,debug,packet     Called-Station-Id = "ICS - South"
echo: radius,debug,packet     NAS-Port-Id = "South"
echo: radius,debug,packet     CHAP-Challenge = 0xda02d1f504ed1009304672a5267ca588
echo: radius,debug,packet     CHAP-Password = 0x01bb33ed9ade5172f3d4f521515eb5d2
echo: radius,debug,packet       42
echo: radius,debug,packet     NAS-Identifier = "ICSAP1-HammettFarms1"
echo: radius,debug,packet     NAS-IP-Address = 10.1.10.100
[admin@ICSAP1-HammettFarms1] > 
  (5 messages discarded)
echo: radius,debug,packet     Framed-Protocol = 1
echo: radius,debug,packet     NAS-Port = 124
echo: radius,debug,packet     NAS-Port-Type = 15
echo: radius,debug,packet     User-Name = "testing123"
echo: radius,debug,packet     Calling-Station-Id = "00:0B:6B:35:AE:C1"
echo: radius,debug,packet     Called-Station-Id = "ICS - South"
echo: radius,debug,packet     NAS-Port-Id = "South"
echo: radius,debug,packet     CHAP-Challenge = 0x5a64b8b84e1be8bc3ca65d06d80a0e6c
echo: radius,debug,packet     CHAP-Password = 0x01f1a99336641496a0aa0416020bf6f7
echo: radius,debug,packet       2d
echo: radius,debug,packet     NAS-Identifier = "ICSAP1-HammettFarms1"
echo: radius,debug,packet     NAS-IP-Address = 10.1.10.100

I then changed it to PAP (removed CHAP and added PAP)

[admin@ICSAP1-HammettFarms1] > 
  (3 messages discarded)
echo: radius,debug,packet     Signature = 0x67458b6bc6237b3269983c6473483366
echo: radius,debug,packet     Service-Type = 2
echo: radius,debug,packet     Framed-Protocol = 1
echo: radius,debug,packet     NAS-Port = 125
echo: radius,debug,packet     NAS-Port-Type = 15
echo: radius,debug,packet     User-Name = "testing123"
echo: radius,debug,packet     Calling-Station-Id = "00:0B:6B:35:AE:C1"
echo: radius,debug,packet     Called-Station-Id = "ICS - South"
echo: radius,debug,packet     NAS-Port-Id = "South"
echo: radius,debug,packet     User-Password = 0x626c6168313233
echo: radius,debug,packet     NAS-Identifier = "ICSAP1-HammettFarms1"
echo: radius,debug,packet     NAS-IP-Address = 10.1.10.100
[admin@ICSAP1-HammettFarms1] > 
  (4 messages discarded)
echo: radius,debug,packet     Framed-Protocol = 1
echo: radius,debug,packet     NAS-Port = 123
echo: radius,debug,packet     NAS-Port-Type = 15
echo: radius,debug,packet     User-Name = "testing123"
echo: radius,debug,packet     Calling-Station-Id = "00:0B:6B:35:AE:C1"
echo: radius,debug,packet     Called-Station-Id = "ICS - South"
echo: radius,debug,packet     NAS-Port-Id = "South"
echo: radius,debug,packet     CHAP-Challenge = 0xda02d1f504ed1009304672a5267ca588
echo: radius,debug,packet     CHAP-Password = 0x01bb33ed9ade5172f3d4f521515eb5d2
echo: radius,debug,packet       42
echo: radius,debug,packet     NAS-Identifier = "ICSAP1-HammettFarms1"
echo: radius,debug,packet     NAS-IP-Address = 10.1.10.100

Then I disabled the interface

[admin@ICSAP1-HammettFarms1] > 
  (4 messages discarded)
echo: radius,debug,packet     Framed-Protocol = 1
echo: radius,debug,packet     NAS-Port = 124
echo: radius,debug,packet     NAS-Port-Type = 15
echo: radius,debug,packet     User-Name = "testing123"
echo: radius,debug,packet     Calling-Station-Id = "00:0B:6B:35:AE:C1"
echo: radius,debug,packet     Called-Station-Id = "ICS - South"
echo: radius,debug,packet     NAS-Port-Id = "South"
echo: radius,debug,packet     CHAP-Challenge = 0x5a64b8b84e1be8bc3ca65d06d80a0e6c
echo: radius,debug,packet     CHAP-Password = 0x01f1a99336641496a0aa0416020bf6f7
echo: radius,debug,packet       2d
echo: radius,debug,packet     NAS-Identifier = "ICSAP1-HammettFarms1"
echo: radius,debug,packet     NAS-IP-Address = 10.1.10.100
[admin@ICSAP1-HammettFarms1] > 
  (2 messages discarded)
echo: radius,debug,packet     Signature = 0x67458b6bc6237b3269983c6473483366
echo: radius,debug,packet     Service-Type = 2
echo: radius,debug,packet     Framed-Protocol = 1
echo: radius,debug,packet     NAS-Port = 125
echo: radius,debug,packet     NAS-Port-Type = 15
echo: radius,debug,packet     User-Name = "testing123"
echo: radius,debug,packet     Calling-Station-Id = "00:0B:6B:35:AE:C1"
echo: radius,debug,packet     Called-Station-Id = "ICS - South"
echo: radius,debug,packet     NAS-Port-Id = "South"
echo: radius,debug,packet     User-Password = 0x626c6168313233
echo: radius,debug,packet     NAS-Identifier = "ICSAP1-HammettFarms1"
echo: radius,debug,packet     NAS-IP-Address = 10.1.10.100
[admin@ICSAP1-HammettFarms1] > 
  (4 messages discarded)
echo: radius,debug,packet     Framed-Protocol = 1
echo: radius,debug,packet     NAS-Port = 123
echo: radius,debug,packet     NAS-Port-Type = 15
echo: radius,debug,packet     User-Name = "testing123"
echo: radius,debug,packet     Calling-Station-Id = "00:0B:6B:35:AE:C1"
echo: radius,debug,packet     Called-Station-Id = "ICS - South"
echo: radius,debug,packet     NAS-Port-Id = "South"
echo: radius,debug,packet     CHAP-Challenge = 0xda02d1f504ed1009304672a5267ca588
echo: radius,debug,packet     CHAP-Password = 0x01bb33ed9ade5172f3d4f521515eb5d2
echo: radius,debug,packet       42
echo: radius,debug,packet     NAS-Identifier = "ICSAP1-HammettFarms1"
echo: radius,debug,packet     NAS-IP-Address = 10.1.10.100
[admin@ICSAP1-HammettFarms1] > 
  (4 messages discarded)
echo: radius,debug,packet     Framed-Protocol = 1
echo: radius,debug,packet     NAS-Port = 124
echo: radius,debug,packet     NAS-Port-Type = 15
echo: radius,debug,packet     User-Name = "testing123"
echo: radius,debug,packet     Calling-Station-Id = "00:0B:6B:35:AE:C1"
echo: radius,debug,packet     Called-Station-Id = "ICS - South"
echo: radius,debug,packet     NAS-Port-Id = "South"
echo: radius,debug,packet     CHAP-Challenge = 0x5a64b8b84e1be8bc3ca65d06d80a0e6c
echo: radius,debug,packet     CHAP-Password = 0x01f1a99336641496a0aa0416020bf6f7
echo: radius,debug,packet       2d
echo: radius,debug,packet     NAS-Identifier = "ICSAP1-HammettFarms1"
echo: radius,debug,packet     NAS-IP-Address = 10.1.10.100
[admin@ICSAP1-HammettFarms1] > 
  (2 messages discarded)
echo: radius,debug,packet     Signature = 0x67458b6bc6237b3269983c6473483366
echo: radius,debug,packet     Service-Type = 2
echo: radius,debug,packet     Framed-Protocol = 1
echo: radius,debug,packet     NAS-Port = 125
echo: radius,debug,packet     NAS-Port-Type = 15
echo: radius,debug,packet     User-Name = "testing123"
echo: radius,debug,packet     Calling-Station-Id = "00:0B:6B:35:AE:C1"
echo: radius,debug,packet     Called-Station-Id = "ICS - South"
echo: radius,debug,packet     NAS-Port-Id = "South"
echo: radius,debug,packet     User-Password = 0x626c6168313233
echo: radius,debug,packet     NAS-Identifier = "ICSAP1-HammettFarms1"
echo: radius,debug,packet     NAS-IP-Address = 10.1.10.100
[admin@ICSAP1-HammettFarms1] > 
echo: radius,debug timeout for 53:00
[admin@ICSAP1-HammettFarms1] > 
echo: radius,debug timeout for 53:01
[admin@ICSAP1-HammettFarms1] > 
echo: radius,debug timeout for 53:02
[admin@ICSAP1-HammettFarms1] >

Why does so much stuff happen after I disable the interface? Why is CHAP still going on after I changed it to PAP?

savage · May 31, 2006, 6:11pm

[admin@ICSAP1-HammettFarms1] >
echo: radius,debug timeout for 53:00
[admin@ICSAP1-HammettFarms1] >
echo: radius,debug timeout for 53:01
[admin@ICSAP1-HammettFarms1] >
echo: radius,debug timeout for 53:02
[admin@ICSAP1-HammettFarms1] >

Heh.

Why does it happen after you disable the interface? The packet only makes it to the AP at that time…

It’s perhaps difficult to grab, but what happens is that the Authentication process between the AP and the CPE times out before the AP gets the reply from the Radius Server… Which is why I said - you must have some SERIOUS latency issues somewhere…

I’m believing more and more that this is a network error somewhere rather than a issue with radius..

Hammy · May 31, 2006, 6:17pm

shakes fists at the air

that doesn’t make sense because that box has decent ping times. Not great, but shouldn’t be an issue…

300 packets transmitted, 300 packets received, 0% packet loss
round-trip min/avg/max = 4/23.5/111 ms

Hammy · May 31, 2006, 6:32pm

argh!

It was due to a VPS configuration… I guess.

I had changed the IP address on the VPS, but for some reason it could still ping the old address. I restarted the VPS and now the client says connected. The VPS must have been sending the packets out with the old IP address, but because it was coming from a different IP, the MT was ignoring it. NTRadping must not be so sensitive to where the reply comes from.

The VPS obviously knew of the new IP or it wouldn’t have gotten the request in the first place… it jsut responded with its former identity.

bows head in shame Thanks much for your help, guys!

savage · May 31, 2006, 7:11pm

Silly mistake, but atleast it’s nailed and we got a GOOD rundown of how radius works

It’s now obvious yes, but a packet sniffer / dump would have shown the incorrect src-address…

Hammy · May 31, 2006, 7:15pm

So now how do I remove the

/system logging add topics=radius,debug action=echo

? :-p

savage · May 31, 2006, 7:42pm

/system logging remove

Hammy · May 31, 2006, 7:53pm

I think you can finally let go of my hand… for this issue. :-p