Dear Freeradius Users: I am trying to use rlm_perl to append a number to one member of the reply packet using rlm_perl and the %RAD_REPLY hash. I am running freeradius-1.1.1. Here is the code that I am using, a modified example.pl: use strict; # use ... # This is very important ! Without this script will not get the filled hashesh from main. use vars qw(%RAD_REQUEST %RAD_REPLY %RAD_CHECK); use vars qw($count_visitor $count_staff $count_student @rad_array); use Data::Dumper; # This is hash wich hold original request from radius #my %RAD_REQUEST; # In this hash you add values that will be returned to NAS. #my %RAD_REPLY; my $count_visitor = 0, $count_staff = 0, $count_student = 0; #This is for check items #my %RAD_CHECK; ... # Function to handle authorize sub authorize { # For debugging purposes only &log_request_attributes; # Here's where your authorization code comes # You can call another function from here: &test_call; if ($RAD_REPLY{'Tunnel-Private-Group-Id'} =~ /visitor/i) { $RAD_REPLY{'Tunnel-Private-Group-Id'} .= $count_visitor % 4; $count_visitor += 1; } elsif ($RAD_REPLY{'Tunnel-Private-Group-Id'} =~ /staff/i) { $RAD_REPLY{'Tunnel-Private-Group-Id'} .= $count_staff % 3; $count_staff += 1; } elsif ($RAD_REPLY{'Tunnel-Private-Group-Id'} =~ /student/i) { $RAD_REPLY{'Tunnel-Private-Group-Id'} .= $count_student % 2; $count_student += 1; } return RLM_MODULE_UPDATED; } ... Here is the debug output from radiusd: /usr/site/freeradius/sbin/radiusd -Xxx Mon Jun 19 18:09:07 2006 : Info: Starting - reading configuration files ... Mon Jun 19 18:09:07 2006 : Debug: reread_config: reading radiusd.conf Mon Jun 19 18:09:07 2006 : Debug: Config: including file: /usr/site/freeradius-1.1.1/etc/raddb/proxy.conf Mon Jun 19 18:09:07 2006 : Debug: Config: including file: /usr/site/freeradius-1.1.1/etc/raddb/clients.conf Mon Jun 19 18:09:07 2006 : Debug: Config: including file: /usr/site/freeradius-1.1.1/etc/raddb/snmp.conf Mon Jun 19 18:09:07 2006 : Debug: Config: including file: /usr/site/freeradius-1.1.1/etc/raddb/eap.conf Mon Jun 19 18:09:07 2006 : Debug: Config: including file: /usr/site/freeradius-1.1.1/etc/raddb/sql.conf Mon Jun 19 18:09:07 2006 : Debug: main: prefix = "/usr/site/freeradius-1.1.1" Mon Jun 19 18:09:07 2006 : Debug: main: localstatedir = "/usr/site/freeradius-1.1.1/var" Mon Jun 19 18:09:07 2006 : Debug: main: logdir = "/usr/site/freeradius-1.1.1/var/log/radius" Mon Jun 19 18:09:07 2006 : Debug: main: libdir = "/usr/site/freeradius-1.1.1/lib" Mon Jun 19 18:09:07 2006 : Debug: main: radacctdir = "/usr/site/freeradius-1.1.1/var/log/radius/radacct" Mon Jun 19 18:09:07 2006 : Debug: main: hostname_lookups = no Mon Jun 19 18:09:07 2006 : Debug: main: snmp = no Mon Jun 19 18:09:07 2006 : Debug: main: max_request_time = 30 Mon Jun 19 18:09:07 2006 : Debug: main: cleanup_delay = 5 Mon Jun 19 18:09:07 2006 : Debug: main: max_requests = 1024 Mon Jun 19 18:09:07 2006 : Debug: main: delete_blocked_requests = 0 Mon Jun 19 18:09:07 2006 : Debug: main: port = 0 Mon Jun 19 18:09:07 2006 : Debug: main: allow_core_dumps = no Mon Jun 19 18:09:07 2006 : Debug: main: log_stripped_names = no Mon Jun 19 18:09:07 2006 : Debug: main: log_file = "/usr/site/freeradius-1.1.1/var/log/radius/radius.log" Mon Jun 19 18:09:07 2006 : Debug: main: log_auth = no Mon Jun 19 18:09:07 2006 : Debug: main: log_auth_badpass = no Mon Jun 19 18:09:07 2006 : Debug: main: log_auth_goodpass = no Mon Jun 19 18:09:07 2006 : Debug: main: pidfile = "/usr/site/freeradius-1.1.1/var/run/radiusd/radiusd.pid" Mon Jun 19 18:09:07 2006 : Debug: main: user = "(null)" Mon Jun 19 18:09:07 2006 : Debug: main: group = "(null)" Mon Jun 19 18:09:07 2006 : Debug: main: usercollide = no Mon Jun 19 18:09:07 2006 : Debug: main: lower_user = "no" Mon Jun 19 18:09:07 2006 : Debug: main: lower_pass = "no" Mon Jun 19 18:09:07 2006 : Debug: main: nospace_user = "no" Mon Jun 19 18:09:07 2006 : Debug: main: nospace_pass = "no" Mon Jun 19 18:09:07 2006 : Debug: main: checkrad = "/usr/site/freeradius-1.1.1/sbin/checkrad" Mon Jun 19 18:09:07 2006 : Debug: main: proxy_requests = yes Mon Jun 19 18:09:07 2006 : Debug: proxy: retry_delay = 5 Mon Jun 19 18:09:07 2006 : Debug: proxy: retry_count = 3 Mon Jun 19 18:09:07 2006 : Debug: proxy: synchronous = no Mon Jun 19 18:09:07 2006 : Debug: proxy: default_fallback = yes Mon Jun 19 18:09:07 2006 : Debug: proxy: dead_time = 120 Mon Jun 19 18:09:07 2006 : Debug: proxy: post_proxy_authorize = no Mon Jun 19 18:09:07 2006 : Debug: proxy: wake_all_if_all_dead = no Mon Jun 19 18:09:07 2006 : Debug: security: max_attributes = 200 Mon Jun 19 18:09:07 2006 : Debug: security: reject_delay = 1 Mon Jun 19 18:09:07 2006 : Debug: security: status_server = no Mon Jun 19 18:09:07 2006 : Debug: main: debug_level = 0 Mon Jun 19 18:09:07 2006 : Debug: read_config_files: reading dictionary Mon Jun 19 18:09:07 2006 : Debug: read_config_files: reading naslist Mon Jun 19 18:09:07 2006 : Info: Using deprecated naslist file. Support for this will go away soon. Mon Jun 19 18:09:07 2006 : Debug: read_config_files: reading clients Mon Jun 19 18:09:07 2006 : Debug: read_config_files: reading realms Mon Jun 19 18:09:07 2006 : Debug: radiusd: entering modules setup Mon Jun 19 18:09:07 2006 : Debug: Module: Library search path is /usr/site/freeradius-1.1.1/lib Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded exec Mon Jun 19 18:09:07 2006 : Debug: exec: wait = yes Mon Jun 19 18:09:07 2006 : Debug: exec: program = "(null)" Mon Jun 19 18:09:07 2006 : Debug: exec: input_pairs = "request" Mon Jun 19 18:09:07 2006 : Debug: exec: output_pairs = "(null)" Mon Jun 19 18:09:07 2006 : Debug: exec: packet_type = "(null)" Mon Jun 19 18:09:07 2006 : Info: rlm_exec: Wait=yes but no output defined. Did you mean output=none? Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated exec (exec) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded expr Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated expr (expr) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded Counter Mon Jun 19 18:09:07 2006 : Debug: counter: filename = "/usr/site/freeradius-1.1.1/etc/raddb/db.vpnrrobin" Mon Jun 19 18:09:07 2006 : Debug: counter: key = "NAS-IP-Address" Mon Jun 19 18:09:07 2006 : Debug: counter: reset = "weekly" Mon Jun 19 18:09:07 2006 : Debug: counter: count-attribute = "User-Name" Mon Jun 19 18:09:07 2006 : Debug: counter: counter-name = "VPN-Connection-Count" Mon Jun 19 18:09:07 2006 : Debug: counter: check-name = "Max-Connection-Count" Mon Jun 19 18:09:07 2006 : Debug: counter: allowed-servicetype = "(null)" Mon Jun 19 18:09:07 2006 : Debug: counter: cache-size = 5000 Mon Jun 19 18:09:07 2006 : Debug: rlm_counter: Counter attribute VPN-Connection-Count is number 1830 Mon Jun 19 18:09:07 2006 : Debug: rlm_counter: Current Time: 1150758547 [2006-06-19 18:09:07], Next reset 1151211600 [2006-06-25 00:00:00] Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated counter (vpnrrobin) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded PAP Mon Jun 19 18:09:07 2006 : Debug: pap: encryption_scheme = "clear" Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated pap (pap) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded CHAP Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated chap (chap) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded MS-CHAP Mon Jun 19 18:09:07 2006 : Debug: mschap: use_mppe = yes Mon Jun 19 18:09:07 2006 : Debug: mschap: require_encryption = no Mon Jun 19 18:09:07 2006 : Debug: mschap: require_strong = no Mon Jun 19 18:09:07 2006 : Debug: mschap: with_ntdomain_hack = no Mon Jun 19 18:09:07 2006 : Debug: mschap: passwd = "(null)" Mon Jun 19 18:09:07 2006 : Debug: mschap: authtype = "MS-CHAP" Mon Jun 19 18:09:07 2006 : Debug: mschap: ntlm_auth = "(null)" Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated mschap (mschap) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded Kerberos Mon Jun 19 18:09:07 2006 : Debug: krb5: keytab = "/etc/opt/heimdal/krb5.keytab" Mon Jun 19 18:09:07 2006 : Debug: krb5: service_principal = "radius/dhcp-a.net.rice.edu@RICE.EDU" Mon Jun 19 18:09:07 2006 : Auth: rlm_krb5: krb5_init ok Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated krb5 (krb5) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded System Mon Jun 19 18:09:07 2006 : Debug: unix: cache = no Mon Jun 19 18:09:07 2006 : Debug: unix: passwd = "(null)" Mon Jun 19 18:09:07 2006 : Debug: unix: shadow = "(null)" Mon Jun 19 18:09:07 2006 : Debug: unix: group = "(null)" Mon Jun 19 18:09:07 2006 : Debug: unix: radwtmp = "/usr/site/freeradius-1.1.1/var/log/radius/radwtmp" Mon Jun 19 18:09:07 2006 : Debug: unix: usegroup = no Mon Jun 19 18:09:07 2006 : Debug: unix: cache_reload = 600 Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated unix (unix) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded eap Mon Jun 19 18:09:07 2006 : Debug: eap: default_eap_type = "tls" Mon Jun 19 18:09:07 2006 : Debug: eap: timer_expire = 60 Mon Jun 19 18:09:07 2006 : Debug: eap: ignore_unknown_eap_types = no Mon Jun 19 18:09:07 2006 : Debug: eap: cisco_accounting_username_bug = no Mon Jun 19 18:09:07 2006 : Debug: rlm_eap: Loaded and initialized type md5 Mon Jun 19 18:09:07 2006 : Debug: rlm_eap: Loaded and initialized type leap Mon Jun 19 18:09:07 2006 : Debug: gtc: challenge = "Password: " Mon Jun 19 18:09:07 2006 : Debug: gtc: auth_type = "PAP" Mon Jun 19 18:09:07 2006 : Debug: rlm_eap: Loaded and initialized type gtc Mon Jun 19 18:09:07 2006 : Debug: tls: rsa_key_exchange = no Mon Jun 19 18:09:07 2006 : Debug: tls: dh_key_exchange = yes Mon Jun 19 18:09:07 2006 : Debug: tls: rsa_key_length = 512 Mon Jun 19 18:09:07 2006 : Debug: tls: dh_key_length = 512 Mon Jun 19 18:09:07 2006 : Debug: tls: verify_depth = 0 Mon Jun 19 18:09:07 2006 : Debug: tls: CA_path = "(null)" Mon Jun 19 18:09:07 2006 : Debug: tls: pem_file_type = yes Mon Jun 19 18:09:07 2006 : Debug: tls: private_key_file = "/etc/opt/ssl/certs/cert.key" Mon Jun 19 18:09:07 2006 : Debug: tls: certificate_file = "/etc/opt/ssl/certs/cert.pem" Mon Jun 19 18:09:07 2006 : Debug: tls: CA_file = "/etc/opt/ssl/certs/CA/cacert.pem" Mon Jun 19 18:09:07 2006 : Debug: tls: private_key_password = "" Mon Jun 19 18:09:07 2006 : Debug: tls: dh_file = "/usr/site/freeradius-1.1.1/etc/raddb/certs/dh" Mon Jun 19 18:09:07 2006 : Debug: tls: random_file = "/usr/site/freeradius-1.1.1/etc/raddb/certs/random" Mon Jun 19 18:09:07 2006 : Debug: tls: fragment_size = 1024 Mon Jun 19 18:09:07 2006 : Debug: tls: include_length = yes Mon Jun 19 18:09:07 2006 : Debug: tls: check_crl = no Mon Jun 19 18:09:07 2006 : Debug: tls: check_cert_cn = "(null)" Mon Jun 19 18:09:07 2006 : Info: rlm_eap_tls: Loading the certificate file as a chain Mon Jun 19 18:09:07 2006 : Debug: rlm_eap: Loaded and initialized type tls Mon Jun 19 18:09:07 2006 : Debug: ttls: default_eap_type = "md5" Mon Jun 19 18:09:07 2006 : Debug: ttls: copy_request_to_tunnel = no Mon Jun 19 18:09:07 2006 : Debug: ttls: use_tunneled_reply = no Mon Jun 19 18:09:07 2006 : Debug: rlm_eap: Loaded and initialized type ttls Mon Jun 19 18:09:07 2006 : Debug: peap: default_eap_type = "mschapv2" Mon Jun 19 18:09:07 2006 : Debug: peap: copy_request_to_tunnel = no Mon Jun 19 18:09:07 2006 : Debug: peap: use_tunneled_reply = no Mon Jun 19 18:09:07 2006 : Debug: peap: proxy_tunneled_request_as_eap = yes Mon Jun 19 18:09:07 2006 : Debug: rlm_eap: Loaded and initialized type peap Mon Jun 19 18:09:07 2006 : Debug: mschapv2: with_ntdomain_hack = no Mon Jun 19 18:09:07 2006 : Debug: rlm_eap: Loaded and initialized type mschapv2 Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated eap (eap) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded preprocess Mon Jun 19 18:09:07 2006 : Debug: preprocess: huntgroups = "/usr/site/freeradius-1.1.1/etc/raddb/huntgroups" Mon Jun 19 18:09:07 2006 : Debug: preprocess: hints = "/usr/site/freeradius-1.1.1/etc/raddb/hints" Mon Jun 19 18:09:07 2006 : Debug: preprocess: with_ascend_hack = no Mon Jun 19 18:09:07 2006 : Debug: preprocess: ascend_channels_per_line = 23 Mon Jun 19 18:09:07 2006 : Debug: preprocess: with_ntdomain_hack = no Mon Jun 19 18:09:07 2006 : Debug: preprocess: with_specialix_jetstream_hack = no Mon Jun 19 18:09:07 2006 : Debug: preprocess: with_cisco_vsa_hack = no Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated preprocess (preprocess) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded realm Mon Jun 19 18:09:07 2006 : Debug: realm: format = "suffix" Mon Jun 19 18:09:07 2006 : Debug: realm: delimiter = "@" Mon Jun 19 18:09:07 2006 : Debug: realm: ignore_default = no Mon Jun 19 18:09:07 2006 : Debug: realm: ignore_null = no Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated realm (suffix) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded files Mon Jun 19 18:09:07 2006 : Debug: files: usersfile = "/usr/site/freeradius-1.1.1/etc/raddb/users" Mon Jun 19 18:09:07 2006 : Debug: files: acctusersfile = "/usr/site/freeradius-1.1.1/etc/raddb/acct_users" Mon Jun 19 18:09:07 2006 : Debug: files: preproxy_usersfile = "/usr/site/freeradius-1.1.1/etc/raddb/preproxy_users" Mon Jun 19 18:09:07 2006 : Debug: files: compat = "no" Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated files (files) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded LDAP Mon Jun 19 18:09:07 2006 : Debug: ldap: server = "ldap1.rice.edu" Mon Jun 19 18:09:07 2006 : Debug: ldap: port = 389 Mon Jun 19 18:09:07 2006 : Debug: ldap: net_timeout = 1 Mon Jun 19 18:09:07 2006 : Debug: ldap: timeout = 4 Mon Jun 19 18:09:07 2006 : Debug: ldap: timelimit = 3 Mon Jun 19 18:09:07 2006 : Debug: ldap: identity = "" Mon Jun 19 18:09:07 2006 : Debug: ldap: tls_mode = no Mon Jun 19 18:09:07 2006 : Debug: ldap: start_tls = no Mon Jun 19 18:09:07 2006 : Debug: ldap: tls_cacertfile = "(null)" Mon Jun 19 18:09:07 2006 : Debug: ldap: tls_cacertdir = "(null)" Mon Jun 19 18:09:07 2006 : Debug: ldap: tls_certfile = "(null)" Mon Jun 19 18:09:07 2006 : Debug: ldap: tls_keyfile = "(null)" Mon Jun 19 18:09:07 2006 : Debug: ldap: tls_randfile = "(null)" Mon Jun 19 18:09:07 2006 : Debug: ldap: tls_require_cert = "allow" Mon Jun 19 18:09:07 2006 : Debug: ldap: password = "" Mon Jun 19 18:09:07 2006 : Debug: ldap: basedn = "ou=People,dc=rice,dc=edu" Mon Jun 19 18:09:07 2006 : Debug: ldap: filter = "(uid=%{Stripped-User-Name:-%{User-Name}})" Mon Jun 19 18:09:07 2006 : Debug: ldap: base_filter = "(objectclass=radiusprofile)" Mon Jun 19 18:09:07 2006 : Debug: ldap: default_profile = "(null)" Mon Jun 19 18:09:07 2006 : Debug: ldap: profile_attribute = "(null)" Mon Jun 19 18:09:07 2006 : Debug: ldap: password_header = "(null)" Mon Jun 19 18:09:07 2006 : Debug: ldap: password_attribute = "(null)" Mon Jun 19 18:09:07 2006 : Debug: ldap: access_attr = "riceClass" Mon Jun 19 18:09:07 2006 : Debug: ldap: groupname_attribute = "cn" Mon Jun 19 18:09:07 2006 : Debug: ldap: groupmembership_filter = "(|(&(objectClass=GroupOfNames)(member=%{Ldap-UserDn}))(&(objectClass=GroupOfUniqueNames)(uniquemember=%{Ldap-UserDn})))" Mon Jun 19 18:09:07 2006 : Debug: ldap: groupmembership_attribute = "(null)" Mon Jun 19 18:09:07 2006 : Debug: ldap: dictionary_mapping = "/usr/site/freeradius-1.1.1/etc/raddb/ldap.attrmap" Mon Jun 19 18:09:07 2006 : Debug: ldap: ldap_debug = 0 Mon Jun 19 18:09:07 2006 : Debug: ldap: ldap_connections_number = 5 Mon Jun 19 18:09:07 2006 : Debug: ldap: compare_check_items = no Mon Jun 19 18:09:07 2006 : Debug: ldap: access_attr_used_for_allow = yes Mon Jun 19 18:09:07 2006 : Debug: ldap: do_xlat = yes Mon Jun 19 18:09:07 2006 : Debug: ldap: set_auth_type = yes Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: Registering ldap_groupcmp for Ldap-Group Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: Registering ldap_xlat with xlat_name ldap Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: Over-riding set_auth_type, as we're not listed in the "authenticate" section. Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: reading ldap<->radius mappings from file /usr/site/freeradius-1.1.1/etc/raddb/ldap.attrmap Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusCheckItem mapped to RADIUS $GENERIC$ Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusReplyItem mapped to RADIUS $GENERIC$ Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusAuthType mapped to RADIUS Auth-Type Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusSimultaneousUse mapped to RADIUS Simultaneous-Use Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusCalledStationId mapped to RADIUS Called-Station-Id Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusCallingStationId mapped to RADIUS Calling-Station-Id Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP lmPassword mapped to RADIUS LM-Password Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP ntPassword mapped to RADIUS NT-Password Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP acctFlags mapped to RADIUS SMB-Account-CTRL-TEXT Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusExpiration mapped to RADIUS Expiration Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusNASIpAddress mapped to RADIUS NAS-IP-Address Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusServiceType mapped to RADIUS Service-Type Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFramedProtocol mapped to RADIUS Framed-Protocol Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFramedIPAddress mapped to RADIUS Framed-IP-Address Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFramedIPNetmask mapped to RADIUS Framed-IP-Netmask Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFramedRoute mapped to RADIUS Framed-Route Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFramedRouting mapped to RADIUS Framed-Routing Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFilterId mapped to RADIUS Filter-Id Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFramedMTU mapped to RADIUS Framed-MTU Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFramedCompression mapped to RADIUS Framed-Compression Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusLoginIPHost mapped to RADIUS Login-IP-Host Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusLoginService mapped to RADIUS Login-Service Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped to RADIUS Login-TCP-Port Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusCallbackNumber mapped to RADIUS Callback-Number Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusCallbackId mapped to RADIUS Callback-Id Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFramedIPXNetwork mapped to RADIUS Framed-IPX-Network Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusClass mapped to RADIUS Class Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusSessionTimeout mapped to RADIUS Session-Timeout Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusIdleTimeout mapped to RADIUS Idle-Timeout Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusTerminationAction mapped to RADIUS Termination-Action Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusLoginLATService mapped to RADIUS Login-LAT-Service Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusLoginLATNode mapped to RADIUS Login-LAT-Node Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped to RADIUS Login-LAT-Group Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink mapped to RADIUS Framed-AppleTalk-Link Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone mapped to RADIUS Framed-AppleTalk-Zone Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusPortLimit mapped to RADIUS Port-Limit Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusLoginLATPort mapped to RADIUS Login-LAT-Port Mon Jun 19 18:09:07 2006 : Debug: rlm_ldap: LDAP radiusReplyMessage mapped to RADIUS Reply-Message Mon Jun 19 18:09:07 2006 : Debug: conns: 0x94d5038 Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated ldap (ldap) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded attr_rewrite Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: attribute = "Class" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: searchfor = "[a-z]* student" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: searchin = "reply" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: replacewith = "student" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: append = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: ignore_case = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: new_attribute = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: max_matches = 10 Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated attr_rewrite (cleanstudent) Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: attribute = "Class" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: searchfor = "faculty" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: searchin = "reply" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: replacewith = "staff" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: append = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: ignore_case = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: new_attribute = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: max_matches = 10 Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated attr_rewrite (cleanfaculty) Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: attribute = "Tunnel-private-group-id" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: searchfor = "[a-z]* student" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: searchin = "reply" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: replacewith = "student" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: append = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: ignore_case = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: new_attribute = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: max_matches = 10 Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated attr_rewrite (cleanstudentw) Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: attribute = "Tunnel-private-group-id" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: searchfor = "faculty" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: searchin = "reply" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: replacewith = "staff" Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: append = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: ignore_case = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: new_attribute = no Mon Jun 19 18:09:07 2006 : Debug: attr_rewrite: max_matches = 10 Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated attr_rewrite (cleanfacultyw) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded perl Mon Jun 19 18:09:07 2006 : Debug: perl: module = "/usr/site/freeradius/etc/raddb/rrobin.pm" Mon Jun 19 18:09:07 2006 : Debug: perl: func_authorize = "authorize" Mon Jun 19 18:09:07 2006 : Debug: perl: func_authenticate = "authenticate" Mon Jun 19 18:09:07 2006 : Debug: perl: func_accounting = "accounting" Mon Jun 19 18:09:07 2006 : Debug: perl: func_preacct = "preacct" Mon Jun 19 18:09:07 2006 : Debug: perl: func_checksimul = "checksimul" Mon Jun 19 18:09:07 2006 : Debug: perl: func_detach = "detach" Mon Jun 19 18:09:07 2006 : Debug: perl: func_xlat = "xlat" Mon Jun 19 18:09:07 2006 : Debug: perl: func_pre_proxy = "pre_proxy" Mon Jun 19 18:09:07 2006 : Debug: perl: func_post_proxy = "post_proxy" Mon Jun 19 18:09:07 2006 : Debug: perl: func_post_auth = "post_auth" Mon Jun 19 18:09:07 2006 : Debug: perl: perl_flags = "(null)" Mon Jun 19 18:09:07 2006 : Debug: perl: func_start_accounting = "(null)" Mon Jun 19 18:09:07 2006 : Debug: perl: func_stop_accounting = "(null)" Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated perl (perl) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded Acct-Unique-Session-Id Mon Jun 19 18:09:07 2006 : Debug: acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated acct_unique (acct_unique) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded detail Mon Jun 19 18:09:07 2006 : Debug: detail: detailfile = "/usr/site/freeradius-1.1.1/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Mon Jun 19 18:09:07 2006 : Debug: detail: detailperm = 384 Mon Jun 19 18:09:07 2006 : Debug: detail: dirperm = 493 Mon Jun 19 18:09:07 2006 : Debug: detail: locking = no Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated detail (detail) Mon Jun 19 18:09:07 2006 : Debug: Module: Loaded radutmp Mon Jun 19 18:09:07 2006 : Debug: radutmp: filename = "/usr/site/freeradius-1.1.1/var/log/radius/radutmp" Mon Jun 19 18:09:07 2006 : Debug: radutmp: username = "%{User-Name}" Mon Jun 19 18:09:07 2006 : Debug: radutmp: case_sensitive = yes Mon Jun 19 18:09:07 2006 : Debug: radutmp: check_with_nas = yes Mon Jun 19 18:09:07 2006 : Debug: radutmp: perm = 384 Mon Jun 19 18:09:07 2006 : Debug: radutmp: callerid = yes Mon Jun 19 18:09:07 2006 : Debug: Module: Instantiated radutmp (radutmp) Mon Jun 19 18:09:07 2006 : Debug: Listening on authentication *:1812 Mon Jun 19 18:09:07 2006 : Debug: Listening on accounting *:1813 Mon Jun 19 18:09:07 2006 : Info: Ready to process requests. rad_recv: Access-Request packet from host 127.0.0.1:33469, id=75, length=61 User-Name = "teststaff" User-Password = "xxxx" NAS-IP-Address = 255.255.255.255 NAS-Port = 13 Mon Jun 19 18:09:26 2006 : Debug: Processing the authorize section of radiusd.conf Mon Jun 19 18:09:26 2006 : Debug: modcall: entering group authorize for request 0 Mon Jun 19 18:09:26 2006 : Debug: modsingle[authorize]: calling preprocess (rlm_preprocess) for request 0 Mon Jun 19 18:09:26 2006 : Debug: modsingle[authorize]: returned from preprocess (rlm_preprocess) for request 0 Mon Jun 19 18:09:26 2006 : Debug: modcall[authorize]: module "preprocess" returns ok for request 0 Mon Jun 19 18:09:26 2006 : Debug: modsingle[authorize]: calling chap (rlm_chap) for request 0 Mon Jun 19 18:09:26 2006 : Debug: modsingle[authorize]: returned from chap (rlm_chap) for request 0 Mon Jun 19 18:09:26 2006 : Debug: modcall[authorize]: module "chap" returns noop for request 0 Mon Jun 19 18:09:26 2006 : Debug: modsingle[authorize]: calling mschap (rlm_mschap) for request 0 Mon Jun 19 18:09:26 2006 : Debug: modsingle[authorize]: returned from mschap (rlm_mschap) for request 0 Mon Jun 19 18:09:26 2006 : Debug: modcall[authorize]: module "mschap" returns noop for request 0 Mon Jun 19 18:09:26 2006 : Debug: modsingle[authorize]: calling suffix (rlm_realm) for request 0 Mon Jun 19 18:09:26 2006 : Debug: rlm_realm: No '@' in User-Name = "teststaff", looking up realm NULL Mon Jun 19 18:09:26 2006 : Debug: rlm_realm: No such realm "NULL" Mon Jun 19 18:09:26 2006 : Debug: modsingle[authorize]: returned from suffix (rlm_realm) for request 0 Mon Jun 19 18:09:26 2006 : Debug: modcall[authorize]: module "suffix" returns noop for request 0 Mon Jun 19 18:09:26 2006 : Debug: modsingle[authorize]: calling eap (rlm_eap) for request 0 Mon Jun 19 18:09:26 2006 : Debug: rlm_eap: No EAP-Message, not doing EAP Mon Jun 19 18:09:26 2006 : Debug: modsingle[authorize]: returned from eap (rlm_eap) for request 0 Mon Jun 19 18:09:26 2006 : Debug: modcall[authorize]: module "eap" returns noop for request 0 Mon Jun 19 18:09:26 2006 : Debug: modsingle[authorize]: calling files (rlm_files) for request 0 Mon Jun 19 18:09:26 2006 : Debug: users: Matched entry DEFAULT at line 203 Mon Jun 19 18:09:26 2006 : Debug: radius_xlat: Running registered xlat function of module ldap for string 'ldap:///dc=rice,dc=edu?riceClass?sub?uid=%u' Mon Jun 19 18:09:26 2006 : Debug: rlm_ldap: - ldap_xlat Mon Jun 19 18:09:26 2006 : Debug: radius_xlat: 'ldap:///dc=rice,dc=edu?riceClass?sub?uid=teststaff' Mon Jun 19 18:09:26 2006 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Mon Jun 19 18:09:26 2006 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Mon Jun 19 18:09:26 2006 : Debug: rlm_ldap: attempting LDAP reconnection Mon Jun 19 18:09:26 2006 : Debug: rlm_ldap: (re)connect to ldap1.rice.edu:389, authentication 0 Mon Jun 19 18:09:26 2006 : Debug: rlm_ldap: bind as / to ldap1.rice.edu:389 Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: waiting for bind result ... Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: Bind was successful Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: performing search in dc=rice,dc=edu, with filter uid=teststaff Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: Adding attribute riceClass, value: staff Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: - ldap_xlat end Mon Jun 19 18:09:31 2006 : Debug: radius_xlat: 'staff' Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: returned from files (rlm_files) for request 0 Mon Jun 19 18:09:31 2006 : Debug: modcall[authorize]: module "files" returns ok for request 0 Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: calling ldap (rlm_ldap) for request 0 Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: - authorize Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: performing user authorization for teststaff Mon Jun 19 18:09:31 2006 : Debug: radius_xlat: '(uid=teststaff)' Mon Jun 19 18:09:31 2006 : Debug: radius_xlat: 'ou=People,dc=rice,dc=edu' Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0 Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0 Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: performing search in ou=People,dc=rice,dc=edu, with filter (uid=teststaff) Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: checking if remote access for teststaff is allowed by riceClass Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: looking for check items in directory... Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: looking for reply items in directory... Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: user teststaff authorized to use remote access Mon Jun 19 18:09:31 2006 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0 Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: returned from ldap (rlm_ldap) for request 0 Mon Jun 19 18:09:31 2006 : Debug: modcall[authorize]: module "ldap" returns ok for request 0 Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: calling cleanstudent (rlm_attr_rewrite) for request 0 Mon Jun 19 18:09:31 2006 : Debug: rlm_attr_rewrite: Could not find value pair for attribute Class Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: returned from cleanstudent (rlm_attr_rewrite) for request 0 Mon Jun 19 18:09:31 2006 : Debug: modcall[authorize]: module "cleanstudent" returns noop for request 0 Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: calling cleanfaculty (rlm_attr_rewrite) for request 0 Mon Jun 19 18:09:31 2006 : Debug: rlm_attr_rewrite: Could not find value pair for attribute Class Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: returned from cleanfaculty (rlm_attr_rewrite) for request 0 Mon Jun 19 18:09:31 2006 : Debug: modcall[authorize]: module "cleanfaculty" returns noop for request 0 Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: calling cleanstudentw (rlm_attr_rewrite) for request 0 Mon Jun 19 18:09:31 2006 : Debug: radius_xlat: '[a-z]* student' Mon Jun 19 18:09:31 2006 : Debug: rlm_attr_rewrite: No match found for attribute Tunnel-private-group-id with value 'staff' Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: returned from cleanstudentw (rlm_attr_rewrite) for request 0 Mon Jun 19 18:09:31 2006 : Debug: modcall[authorize]: module "cleanstudentw" returns ok for request 0 Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: calling cleanfacultyw (rlm_attr_rewrite) for request 0 Mon Jun 19 18:09:31 2006 : Debug: radius_xlat: 'faculty' Mon Jun 19 18:09:31 2006 : Debug: rlm_attr_rewrite: No match found for attribute Tunnel-private-group-id with value 'staff' Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: returned from cleanfacultyw (rlm_attr_rewrite) for request 0 Mon Jun 19 18:09:31 2006 : Debug: modcall[authorize]: module "cleanfacultyw" returns ok for request 0 Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: calling vpnrrobin (rlm_counter) for request 0 Mon Jun 19 18:09:31 2006 : Debug: rlm_counter: Entering module authorize code Mon Jun 19 18:09:31 2006 : Debug: rlm_counter: Could not find Check item value pair Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: returned from vpnrrobin (rlm_counter) for request 0 Mon Jun 19 18:09:31 2006 : Debug: modcall[authorize]: module "vpnrrobin" returns noop for request 0 Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: calling perl (rlm_perl) for request 0 Mon Jun 19 18:09:31 2006 : Debug: Using perl at 0x94d7920 Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: RAD_REQUEST: Client-IP-Address = 127.0.0.1 Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: RAD_REQUEST: User-Name = teststaff Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: RAD_REQUEST: User-Password = xxxxx Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: RAD_REQUEST: Ldap-UserDn = uid=teststaff,ou=People,dc=rice,dc=edu Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: RAD_REQUEST: NAS-Port = 13 Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: RAD_REQUEST: NAS-IP-Address = 255.255.255.255 Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: RAD_REPLY: Tunnel-Medium-Type = IEEE-802 Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: RAD_REPLY: Tunnel-Type = VLAN Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: RAD_REPLY: Tunnel-Private-Group-Id = staff Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: Added pair Tunnel-Medium-Type = IEEE-802 Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: Added pair Tunnel-Type = VLAN Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: Added pair Tunnel-Private-Group-Id = staff0 Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: Added pair Auth-Type = Kerberos Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: Added pair NAS-Port = 13 Mon Jun 19 18:09:31 2006 : Debug: rlm_perl: Added pair NAS-IP-Address = 255.255.255.255 Mon Jun 19 18:09:31 2006 : Debug: modsingle[authorize]: returned from perl (rlm_perl) for request 0 Mon Jun 19 18:09:31 2006 : Debug: modcall[authorize]: module "perl" returns updated for request 0 Mon Jun 19 18:09:31 2006 : Debug: modcall: leaving group authorize (returns updated) for request 0 Mon Jun 19 18:09:31 2006 : Debug: rad_check_password: Found Auth-Type Kerberos Mon Jun 19 18:09:31 2006 : Debug: auth: type "Kerberos" Mon Jun 19 18:09:31 2006 : Debug: Processing the authenticate section of radiusd.conf Mon Jun 19 18:09:31 2006 : Debug: modcall: entering group authenticate for request 0 Mon Jun 19 18:09:31 2006 : Debug: modsingle[authenticate]: calling krb5 (rlm_krb5) for request 0 Mon Jun 19 18:09:31 2006 : Auth: rlm_krb5: Parsed name is: teststaff@RICE.EDU Mon Jun 19 18:09:31 2006 : Debug: modsingle[authenticate]: returned from krb5 (rlm_krb5) for request 0 Mon Jun 19 18:09:31 2006 : Debug: modcall[authenticate]: module "krb5" returns ok for request 0 Mon Jun 19 18:09:31 2006 : Debug: modcall: leaving group authenticate (returns ok) for request 0 Sending Access-Accept of id 75 to 127.0.0.1 port 33469 Tunnel-Type:0 = VLAN Tunnel-Medium-Type:0 = IEEE-802 Tunnel-Private-Group-Id:0 = "staff" Mon Jun 19 18:09:31 2006 : Debug: Finished request 0 Mon Jun 19 18:09:31 2006 : Debug: Going to the next request Mon Jun 19 18:09:31 2006 : Debug: --- Walking the entire request list --- Mon Jun 19 18:09:31 2006 : Debug: Waking up in 6 seconds... rad_recv: Access-Request packet from host 127.0.0.1:33469, id=75, length=61 Mon Jun 19 18:09:31 2006 : Debug: Sending duplicate reply to client localhost:33469 - ID: 75 Re-sending Access-Accept of id 75 to 127.0.0.1 port 33469 Mon Jun 19 18:09:31 2006 : Debug: --- Walking the entire request list --- Mon Jun 19 18:09:31 2006 : Debug: Waking up in 1 seconds... Mon Jun 19 18:09:32 2006 : Debug: --- Walking the entire request list --- Mon Jun 19 18:09:32 2006 : Debug: Cleaning up request 0 ID 75 with timestamp 44972ea6 Mon Jun 19 18:09:32 2006 : Debug: Nothing to do. Sleeping until we see a request. ----------------------- As you can see from the log, a new reply pair is added for the Tunnel-Private-Group-ID instead of updating the existing one. The initial one is populated via LDAP and I am using rlm_perl to manage the load balancing of the individual VLANs. Is there a way to have rlm_perl change the actual contents of the reply packet so that the correct VLAN entry is returned? If not, does anyone have a good idea about how that may be accomplished? Ken Marshall