Exec program debugging.

[Eliot, Wireless and Server Administrator, Great Lakes Internet]

I am trying to execute a program in the post-proxy section on
Access-Accept packets to bring up bandwidth management for a user when
they log in:

(radiusd.conf)

  exec bwup {
    wait = no;
    program = "/etc/raddb/bwlimit start %{User-Name}
%{Calling-Station-Id} %{Tunnel-Private-Group-Id:0} %{NAS-Port}
%{GLI-Rx-Data-Rate} %{GLI-Tx-Data-Rate}"
    input_pairs = reply
    packet_type = Access-Accept
    output = none
  }

post-proxy {
# post_proxy_log
# attr_rewrite
# attr_filter
  exec
  eap
}

However, the exec call keeps failing when called from inside radiusd -X:


Ready to process requests.
rad_recv: Access-Request packet from host xxx.xxx.6.99:1645, id=3,
length=128
        User-Name = ""
        Framed-MTU = 1400
        Called-Station-Id = "00-13-19-36-C4-52"
        Calling-Station-Id = "00-13-D3-67-D7-05"
        Service-Type = Login-User
        Message-Authenticator = 0x43483d78f3b3f25bcb7657f1522050ef
        EAP-Message = 0x0202000501
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 262
        NAS-IP-Address = xxx.xxx.6.99
        NAS-Identifier = "xxxx-Ch11"
  Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
  modcall[authorize]: module "preprocess" returns ok for request 0
  modcall[authorize]: module "mschap" returns noop for request 0
    rlm_realm: No '@' in User-Name = "", looking up realm NULL
    rlm_realm: Found realm "NULL"
    rlm_realm: Adding Stripped-User-Name = ""
    rlm_realm: Proxying request from user  to realm NULL
    rlm_realm: Adding Realm = "NULL"
    rlm_realm: Preparing to proxy authentication request to realm "NULL"
  modcall[authorize]: module "suffix" returns updated for request 0
  rlm_eap: Request is supposed to be proxied to Realm NULL.  Not doing
EAP.
  modcall[authorize]: module "eap" returns noop for request 0
modcall: group authorize returns updated for request 0
Sending Access-Request of id 0 to xxx.xxx.178.13:1645
        User-Name = ""
        Framed-MTU = 1400
        Called-Station-Id = "00-13-19-36-C4-52"
        Calling-Station-Id = "00-13-D3-67-D7-05"
        Service-Type = Login-User
        Message-Authenticator = 0x00000000000000000000000000000000
        EAP-Message = 0x0202000501
        NAS-Port-Type = Wireless-802.11
        NAS-Port = 262
        NAS-IP-Address = xxx.xxx.6.99
        NAS-Identifier = "xxxx-Ch11"
        Proxy-State = 0x33
--- Walking the entire request list ---
Waking up in 6 seconds...
rad_recv: Access-Challenge packet from host xxx.xxx.178.13:1645, id=0,
length=80
        Proxy-State = 0x33
        Session-Timeout = 30
        EAP-Message = 0x010300061920
        State = 0x1cc30355000001370001d819b406000000034b872b6f01
        Message-Authenticator = 0x2153f90d4c19a27ae054f7f297611c86
  Processing the post-proxy section of radiusd.conf
modcall: entering group post-proxy for request 0
rlm_exec (exec): We require a program to execute
  modcall[post-proxy]: module "exec" returns fail for request 0
modcall: group post-proxy returns fail for request 0
Going to the next request
--- Walking the entire request list ---
Waking up in 31 seconds...


But, if I take the values from a valid Access-Accept packet for the
attributes listed above, the file executes correctly with no errors:

wireless-r1 raddb # su - radiusd
radiusd at wireless-r1 ~ $ /etc/raddb/bwlimit start egable
00:a0:12:34:56:78 3 7 1024 512
radiusd at wireless-r1 ~ $ /etc/raddb/bwlimit stop egable
radiusd at wireless-r1 ~ $ exit
logout
wireless-r1 raddb #

All of my rules get added correctly when issuing a start command and
they get removed correctly when issuing the stop command, but only if I
issue the commands from the command line. 

If I add more Xs to the -X, it still doesn't tell me why it is failing
(what the specific error message is):

Mon Mar 20 13:32:45 2006 : Debug:   Processing the post-proxy section of
radiusd.conf
Mon Mar 20 13:32:45 2006 : Debug: modcall: entering group post-proxy for
request 0
Mon Mar 20 13:32:45 2006 : Debug:   modsingle[post-proxy]: calling exec
(rlm_exec) for request 0
Mon Mar 20 13:32:45 2006 : Error: rlm_exec (exec): We require a program
to execute
Mon Mar 20 13:32:45 2006 : Debug:   modsingle[post-proxy]: returned from
exec (rlm_exec) for request 0
Mon Mar 20 13:32:45 2006 : Debug:   modcall[post-proxy]: module "exec"
returns fail for request 0
Mon Mar 20 13:32:45 2006 : Debug: modcall: group post-proxy returns fail
for request 0
Mon Mar 20 13:32:45 2006 : Debug: Going to the next request
Mon Mar 20 13:32:45 2006 : Debug: rl_next:  returning NULL
Mon Mar 20 13:32:45 2006 : Debug: Waking up in 6 seconds...


I am assuming I just have the configuration for this set up wrong or
something. Obviously, the Access-Accept packet is not yet coming back
because the first Access-Challenge hasn't even been passed on to the AP
yet. So, I'm not sure why the post-proxy section even wants to fire the
program at this point in the authentication process. Does anyone know
what I did wrong?

Thanks.


 
Eliot Gable
Certified Wireless Network Administrator (CWNA)
Certified Wireless Security Professional (CWSP)
Cisco Certified Network Associate (CCNA)
CompTIA Security+ Certified
CompTIA Network+ Certified
Network and Systems Administrator
Great Lakes Internet, Inc.
112 North Howard
Croswell, MI 48422
(810) 679-3395
(877) 558-8324
 
Now offering Broadband Wireless Internet access in Croswell, Lexington,
Brown City, Yale, and Sandusky. Call for details.