Can't authenticate users on LDAP Server by FreeRadius

[Luís Cláudio Veiga]

Hi everybody,
specially Alan Dekok, Ivan Kallik and people trying to do this work.

[root at freeradius_server1 ~]# radiusd -X -A -xxx
Thu Feb 27 12:07:00 2014 : Info: Starting - reading configuration files ...
Thu Feb 27 12:07:00 2014 : Debug: reread_config:  reading radiusd.conf
Thu Feb 27 12:07:00 2014 : Debug: Config:   including file:
/etc/raddb/proxy.conf
Thu Feb 27 12:07:00 2014 : Debug: Config:   including file:
/etc/raddb/clients.conf
Thu Feb 27 12:07:00 2014 : Debug: Config:   including file:
/etc/raddb/snmp.conf
Thu Feb 27 12:07:00 2014 : Debug: Config:   including file:
/etc/raddb/eap.conf
Thu Feb 27 12:07:00 2014 : Debug:  main: prefix = "/usr"
Thu Feb 27 12:07:00 2014 : Debug:  main: localstatedir = "/var"
Thu Feb 27 12:07:00 2014 : Debug:  main: logdir = "/var/log/radius"
Thu Feb 27 12:07:00 2014 : Debug:  main: libdir = "/usr/lib"
Thu Feb 27 12:07:00 2014 : Debug:  main: radacctdir =
"/var/log/radius/radacct"
Thu Feb 27 12:07:00 2014 : Debug:  main: hostname_lookups = no
Thu Feb 27 12:07:00 2014 : Debug:  main: snmp = no
Thu Feb 27 12:07:00 2014 : Debug:  main: max_request_time = 60
Thu Feb 27 12:07:00 2014 : Debug:  main: cleanup_delay = 6
Thu Feb 27 12:07:00 2014 : Debug:  main: max_requests = 4096
Thu Feb 27 12:07:00 2014 : Debug:  main: delete_blocked_requests = 0
Thu Feb 27 12:07:00 2014 : Debug:  main: port = 1812
Thu Feb 27 12:07:00 2014 : Debug:  main: allow_core_dumps = no
Thu Feb 27 12:07:00 2014 : Debug:  main: log_stripped_names = no
Thu Feb 27 12:07:00 2014 : Debug:  main: log_file =
"/var/log/radius/radius.log"
Thu Feb 27 12:07:00 2014 : Debug:  main: log_auth = yes
Thu Feb 27 12:07:00 2014 : Debug:  main: log_auth_badpass = yes
Thu Feb 27 12:07:00 2014 : Debug:  main: log_auth_goodpass = yes
Thu Feb 27 12:07:00 2014 : Debug:  main: pidfile =
"/var/run/radiusd/radiusd.pid"
Thu Feb 27 12:07:00 2014 : Debug:  main: user = "root"
Thu Feb 27 12:07:00 2014 : Debug:  main: group = "root"
Thu Feb 27 12:07:00 2014 : Debug:  main: usercollide = no
Thu Feb 27 12:07:00 2014 : Debug:  main: lower_user = "no"
Thu Feb 27 12:07:00 2014 : Debug:  main: lower_pass = "no"
Thu Feb 27 12:07:00 2014 : Debug:  main: nospace_user = "no"
Thu Feb 27 12:07:00 2014 : Debug:  main: nospace_pass = "no"
Thu Feb 27 12:07:00 2014 : Debug:  main: checkrad = "/usr/sbin/checkrad"
Thu Feb 27 12:07:00 2014 : Debug:  main: proxy_requests = no
Thu Feb 27 12:07:00 2014 : Debug:  proxy: retry_delay = 5
Thu Feb 27 12:07:00 2014 : Debug:  proxy: retry_count = 3
Thu Feb 27 12:07:00 2014 : Debug:  proxy: synchronous = no
Thu Feb 27 12:07:00 2014 : Debug:  proxy: default_fallback = yes
Thu Feb 27 12:07:00 2014 : Debug:  proxy: dead_time = 120
Thu Feb 27 12:07:00 2014 : Debug:  proxy: post_proxy_authorize = yes
Thu Feb 27 12:07:00 2014 : Debug:  proxy: wake_all_if_all_dead = no
Thu Feb 27 12:07:00 2014 : Debug:  security: max_attributes = 200
Thu Feb 27 12:07:00 2014 : Debug:  security: reject_delay = 3
Thu Feb 27 12:07:00 2014 : Debug:  security: status_server = no
Thu Feb 27 12:07:00 2014 : Debug:  main: debug_level = 0
Thu Feb 27 12:07:00 2014 : Debug: read_config_files:  reading dictionary
Thu Feb 27 12:07:00 2014 : Debug: read_config_files:  reading naslist
Thu Feb 27 12:07:00 2014 : Info: Using deprecated naslist file.  Support
for this will go away soon.
Thu Feb 27 12:07:00 2014 : Debug: read_config_files:  reading clients
Thu Feb 27 12:07:00 2014 : Debug: read_config_files:  reading realms
Thu Feb 27 12:07:00 2014 : Debug: radiusd:  entering modules setup
Thu Feb 27 12:07:00 2014 : Debug: Module: Library search path is /usr/lib
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded exec
Thu Feb 27 12:07:00 2014 : Debug:  exec: wait = yes
Thu Feb 27 12:07:00 2014 : Debug:  exec: program = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  exec: input_pairs = "request"
Thu Feb 27 12:07:00 2014 : Debug:  exec: output_pairs = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  exec: packet_type = "(null)"
Thu Feb 27 12:07:00 2014 : Info: rlm_exec: Wait=yes but no output defined.
Did you mean output=none?
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated exec (exec)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded expr
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated expr (expr)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded PAP
Thu Feb 27 12:07:00 2014 : Debug:  pap: encryption_scheme = "clear"
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated pap (pap)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded CHAP
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated chap (chap)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded MS-CHAP
Thu Feb 27 12:07:00 2014 : Debug:  mschap: use_mppe = yes
Thu Feb 27 12:07:00 2014 : Debug:  mschap: require_encryption = no
Thu Feb 27 12:07:00 2014 : Debug:  mschap: require_strong = no
Thu Feb 27 12:07:00 2014 : Debug:  mschap: with_ntdomain_hack = no
Thu Feb 27 12:07:00 2014 : Debug:  mschap: passwd = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  mschap: ntlm_auth = "(null)"
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated mschap (mschap)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded System
Thu Feb 27 12:07:00 2014 : Debug:  unix: cache = no
Thu Feb 27 12:07:00 2014 : Debug:  unix: passwd = "/etc/passwd"
Thu Feb 27 12:07:00 2014 : Debug:  unix: shadow = "/etc/shadow"
Thu Feb 27 12:07:00 2014 : Debug:  unix: group = "/etc/group"
Thu Feb 27 12:07:00 2014 : Debug:  unix: radwtmp = "/var/log/radius/radwtmp"
Thu Feb 27 12:07:00 2014 : Debug:  unix: usegroup = no
Thu Feb 27 12:07:00 2014 : Debug:  unix: cache_reload = 600
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated unix (unix)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded LDAP
Thu Feb 27 12:07:00 2014 : Debug:  ldap: server = "
myadserver.MYCOMPANY.net.br"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: port = 389
Thu Feb 27 12:07:00 2014 : Debug:  ldap: net_timeout = 1
Thu Feb 27 12:07:00 2014 : Debug:  ldap: timeout = 4
Thu Feb 27 12:07:00 2014 : Debug:  ldap: timelimit = 20
Thu Feb 27 12:07:00 2014 : Debug:  ldap: identity =
"CN=AUTHENTIC,CN=USERS,DC=MYCOMPANY,DC=NET,DC=BR"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: tls_mode = no
Thu Feb 27 12:07:00 2014 : Debug:  ldap: start_tls = no
Thu Feb 27 12:07:00 2014 : Debug:  ldap: tls_cacertfile = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: tls_cacertdir = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: tls_certfile = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: tls_keyfile = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: tls_randfile = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: tls_require_cert = "allow"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: password = "adpasswd"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: basedn =
"CN=USERS,DC=MYCOMPANY,DC=NET,DC=BR"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: filter =
"(&(sAMAccountname=%{Stripped-User-Name:-%{User-Name}})(objectClass=user))"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: base_filter =
"(objectclass=posixAccount)"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: default_profile = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: profile_attribute = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: password_header = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: password_attribute = "userPassword"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: access_attr = "SamAccountName"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: groupname_attribute = "cn"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: groupmembership_filter =
"(&(objectClass=group)(member=%{Ldap-UserDn}))"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: groupmembership_attribute =
"memberOf"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: dictionary_mapping =
"/etc/raddb/ldap.attrmap"
Thu Feb 27 12:07:00 2014 : Debug:  ldap: ldap_debug = 0
Thu Feb 27 12:07:00 2014 : Debug:  ldap: ldap_connections_number = 30
Thu Feb 27 12:07:00 2014 : Debug:  ldap: compare_check_items = yes
Thu Feb 27 12:07:00 2014 : Debug:  ldap: access_attr_used_for_allow = yes
Thu Feb 27 12:07:00 2014 : Debug:  ldap: do_xlat = yes
Thu Feb 27 12:07:00 2014 : Debug:  ldap: set_auth_type = yes
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: Registering ldap_groupcmp for
Ldap-Group
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: Registering ldap_xlat with
xlat_name ldap
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: reading ldap<->radius mappings
from file /etc/raddb/ldap.attrmap
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusCheckItem mapped to
RADIUS $GENERIC$
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusReplyItem mapped to
RADIUS $GENERIC$
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusAuthType mapped to
RADIUS Auth-Type
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusSimultaneousUse
mapped to RADIUS Simultaneous-Use
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusCalledStationId
mapped to RADIUS Called-Station-Id
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusCallingStationId
mapped to RADIUS Calling-Station-Id
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP sambaLMPassword mapped to
RADIUS LM-Password
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP sambaNTPassword mapped to
RADIUS NT-Password
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP sambaAcctFlags mapped to
RADIUS SMB-Account-CTRL-TEXT
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusExpiration mapped to
RADIUS Expiration
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusNASIpAddress mapped
to RADIUS NAS-IP-Address
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusServiceType mapped
to RADIUS Service-Type
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusFramedProtocol
mapped to RADIUS Framed-Protocol
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusFramedIPAddress
mapped to RADIUS Framed-IP-Address
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusFramedIPNetmask
mapped to RADIUS Framed-IP-Netmask
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusFramedRoute mapped
to RADIUS Framed-Route
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusFramedRouting mapped
to RADIUS Framed-Routing
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusFilterId mapped to
RADIUS Filter-Id
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusFramedMTU mapped to
RADIUS Framed-MTU
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusFramedCompression
mapped to RADIUS Framed-Compression
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusLoginIPHost mapped
to RADIUS Login-IP-Host
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusLoginService mapped
to RADIUS Login-Service
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusLoginTCPPort mapped
to RADIUS Login-TCP-Port
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusCallbackNumber
mapped to RADIUS Callback-Number
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusCallbackId mapped to
RADIUS Callback-Id
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusFramedIPXNetwork
mapped to RADIUS Framed-IPX-Network
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusClass mapped to
RADIUS Class
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusSessionTimeout
mapped to RADIUS Session-Timeout
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusIdleTimeout mapped
to RADIUS Idle-Timeout
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusTerminationAction
mapped to RADIUS Termination-Action
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusLoginLATService
mapped to RADIUS Login-LAT-Service
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusLoginLATNode mapped
to RADIUS Login-LAT-Node
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusLoginLATGroup mapped
to RADIUS Login-LAT-Group
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkLink
mapped to RADIUS Framed-AppleTalk-Link
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP
radiusFramedAppleTalkNetwork mapped to RADIUS Framed-AppleTalk-Network
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusFramedAppleTalkZone
mapped to RADIUS Framed-AppleTalk-Zone
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusPortLimit mapped to
RADIUS Port-Limit
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusLoginLATPort mapped
to RADIUS Login-LAT-Port
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP radiusReplyMessage mapped
to RADIUS Reply-Message
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP AcmeUserPrivilege mapped
to RADIUS Service-Type
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP AcmeUserClass mapped to
RADIUS Service-Type
Thu Feb 27 12:07:00 2014 : Debug: rlm_ldap: LDAP Cisco-AVPair mapped to
RADIUS Cisco-AVPair
Thu Feb 27 12:07:00 2014 : Debug: conns: 0x8ac0db0
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated ldap (ldap)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded eap
Thu Feb 27 12:07:00 2014 : Debug:  eap: default_eap_type = "peap"
Thu Feb 27 12:07:00 2014 : Debug:  eap: timer_expire = 60
Thu Feb 27 12:07:00 2014 : Debug:  eap: ignore_unknown_eap_types = no
Thu Feb 27 12:07:00 2014 : Debug:  eap: cisco_accounting_username_bug = no
Thu Feb 27 12:07:00 2014 : Debug: rlm_eap: Loaded and initialized type md5
Thu Feb 27 12:07:00 2014 : Debug: rlm_eap: Loaded and initialized type leap
Thu Feb 27 12:07:00 2014 : Debug:  gtc: challenge = "Password: "
Thu Feb 27 12:07:00 2014 : Debug:  gtc: auth_type = "PAP"
Thu Feb 27 12:07:00 2014 : Debug: rlm_eap: Loaded and initialized type gtc
Thu Feb 27 12:07:00 2014 : Debug:  tls: rsa_key_exchange = no
Thu Feb 27 12:07:00 2014 : Debug:  tls: dh_key_exchange = yes
Thu Feb 27 12:07:00 2014 : Debug:  tls: rsa_key_length = 512
Thu Feb 27 12:07:00 2014 : Debug:  tls: dh_key_length = 512
Thu Feb 27 12:07:00 2014 : Debug:  tls: verify_depth = 0
Thu Feb 27 12:07:00 2014 : Debug:  tls: CA_path = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  tls: pem_file_type = yes
Thu Feb 27 12:07:00 2014 : Debug:  tls: private_key_file =
"/etc/raddb/certs/cert-srv.pem"
Thu Feb 27 12:07:00 2014 : Debug:  tls: certificate_file =
"/etc/raddb/certs/cert-srv.pem"
Thu Feb 27 12:07:00 2014 : Debug:  tls: CA_file =
"/etc/raddb/certs/demoCA/cacert.pem"
Thu Feb 27 12:07:00 2014 : Debug:  tls: private_key_password = "whatever"
Thu Feb 27 12:07:00 2014 : Debug:  tls: dh_file = "/etc/raddb/certs/dh"
Thu Feb 27 12:07:00 2014 : Debug:  tls: random_file =
"/etc/raddb/certs/random"
Thu Feb 27 12:07:00 2014 : Debug:  tls: fragment_size = 1024
Thu Feb 27 12:07:00 2014 : Debug:  tls: include_length = yes
Thu Feb 27 12:07:00 2014 : Debug:  tls: check_crl = no
Thu Feb 27 12:07:00 2014 : Debug:  tls: check_cert_cn = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  tls: cipher_list = "(null)"
Thu Feb 27 12:07:00 2014 : Debug:  tls: check_cert_issuer = "(null)"
Thu Feb 27 12:07:00 2014 : Info: rlm_eap_tls: Loading the certificate file
as a chain
Thu Feb 27 12:07:00 2014 : Debug: rlm_eap: Loaded and initialized type tls
Thu Feb 27 12:07:00 2014 : Debug:  ttls: default_eap_type = "md5"
Thu Feb 27 12:07:00 2014 : Debug:  ttls: copy_request_to_tunnel = no
Thu Feb 27 12:07:00 2014 : Debug:  ttls: use_tunneled_reply = no
Thu Feb 27 12:07:00 2014 : Debug: rlm_eap: Loaded and initialized type ttls
Thu Feb 27 12:07:00 2014 : Debug:  peap: default_eap_type = "mschapv2"
Thu Feb 27 12:07:00 2014 : Debug:  peap: copy_request_to_tunnel = no
Thu Feb 27 12:07:00 2014 : Debug:  peap: use_tunneled_reply = no
Thu Feb 27 12:07:00 2014 : Debug:  peap: proxy_tunneled_request_as_eap = yes
Thu Feb 27 12:07:00 2014 : Debug: rlm_eap: Loaded and initialized type peap
Thu Feb 27 12:07:00 2014 : Debug:  mschapv2: with_ntdomain_hack = no
Thu Feb 27 12:07:00 2014 : Debug: rlm_eap: Loaded and initialized type
mschapv2
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated eap (eap)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded preprocess
Thu Feb 27 12:07:00 2014 : Debug:  preprocess: huntgroups =
"/etc/raddb/huntgroups"
Thu Feb 27 12:07:00 2014 : Debug:  preprocess: hints = "/etc/raddb/hints"
Thu Feb 27 12:07:00 2014 : Debug:  preprocess: with_ascend_hack = no
Thu Feb 27 12:07:00 2014 : Debug:  preprocess: ascend_channels_per_line = 23
Thu Feb 27 12:07:00 2014 : Debug:  preprocess: with_ntdomain_hack = no
Thu Feb 27 12:07:00 2014 : Debug:  preprocess:
with_specialix_jetstream_hack = no
Thu Feb 27 12:07:00 2014 : Debug:  preprocess: with_cisco_vsa_hack = no
Thu Feb 27 12:07:00 2014 : Debug:  preprocess: with_alvarion_vsa_hack = no
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated preprocess
(preprocess)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded detail
Thu Feb 27 12:07:00 2014 : Debug:  detail: detailfile =
"/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d"
Thu Feb 27 12:07:00 2014 : Debug:  detail: detailperm = 384
Thu Feb 27 12:07:00 2014 : Debug:  detail: dirperm = 493
Thu Feb 27 12:07:00 2014 : Debug:  detail: locking = no
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated detail (auth_log)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded files
Thu Feb 27 12:07:00 2014 : Debug:  files: usersfile = "/etc/raddb/users"
Thu Feb 27 12:07:00 2014 : Debug:  files: acctusersfile =
"/etc/raddb/acct_users"
Thu Feb 27 12:07:00 2014 : Debug:  files: preproxy_usersfile =
"/etc/raddb/preproxy_users"
Thu Feb 27 12:07:00 2014 : Debug:  files: compat = "no"
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated files (files)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded Acct-Unique-Session-Id
Thu Feb 27 12:07:00 2014 : Debug:  acct_unique: key = "User-Name,
Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated acct_unique
(acct_unique)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded realm
Thu Feb 27 12:07:00 2014 : Debug:  realm: format = "suffix"
Thu Feb 27 12:07:00 2014 : Debug:  realm: delimiter = "@"
Thu Feb 27 12:07:00 2014 : Debug:  realm: ignore_default = no
Thu Feb 27 12:07:00 2014 : Debug:  realm: ignore_null = no
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated realm (suffix)
Thu Feb 27 12:07:00 2014 : Debug:  detail: detailfile =
"/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Thu Feb 27 12:07:00 2014 : Debug:  detail: detailperm = 384
Thu Feb 27 12:07:00 2014 : Debug:  detail: dirperm = 493
Thu Feb 27 12:07:00 2014 : Debug:  detail: locking = no
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated detail (detail)
Thu Feb 27 12:07:00 2014 : Debug: Module: Loaded radutmp
Thu Feb 27 12:07:00 2014 : Debug:  radutmp: filename =
"/var/log/radius/radutmp"
Thu Feb 27 12:07:00 2014 : Debug:  radutmp: username = "%{User-Name}"
Thu Feb 27 12:07:00 2014 : Debug:  radutmp: case_sensitive = yes
Thu Feb 27 12:07:00 2014 : Debug:  radutmp: check_with_nas = yes
Thu Feb 27 12:07:00 2014 : Debug:  radutmp: perm = 384
Thu Feb 27 12:07:00 2014 : Debug:  radutmp: callerid = yes
Thu Feb 27 12:07:00 2014 : Debug: Module: Instantiated radutmp (radutmp)
Thu Feb 27 12:07:00 2014 : Debug: Listening on authentication *:1812
Thu Feb 27 12:07:00 2014 : Debug: Listening on accounting *:1813
Thu Feb 27 12:07:00 2014 : Info: Ready to process requests.
rad_recv: Access-Request packet from host 10.253.7.156:1812, id=157,
length=63
        User-Name = "username"
        User-Password = "userpassword"
        NAS-Identifier = "NGN"
        NAS-IP-Address = 10.253.7.156
        NAS-Port = 118751232
Thu Feb 27 12:07:11 2014 : Debug:   Processing the authorize section of
radiusd.conf
Thu Feb 27 12:07:11 2014 : Debug: modcall: entering group authorize for
request 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modcall[authorize]: module "preprocess"
returns ok for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: calling auth_log
(rlm_detail) for request 0
Thu Feb 27 12:07:11 2014 : Debug: radius_xlat:  '/var/log/radius/radacct/
10.253.7.156/auth-detail-20140227'
Thu Feb 27 12:07:11 2014 : Debug: rlm_detail:
/var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to
/var/log/radius/radacct/10.253.7.156/auth-detail-20140227
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: returned from
auth_log (rlm_detail) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modcall[authorize]: module "auth_log"
returns ok for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: calling chap
(rlm_chap) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: returned from
chap (rlm_chap) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modcall[authorize]: module "chap"
returns noop for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: calling mschap
(rlm_mschap) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: returned from
mschap (rlm_mschap) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modcall[authorize]: module "mschap"
returns noop for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: calling eap
(rlm_eap) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   rlm_eap: No EAP-Message, not doing EAP
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: returned from eap
(rlm_eap) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modcall[authorize]: module "eap"
returns noop for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: calling ldap
(rlm_ldap) for request 0
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: - authorize
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: performing user authorization
for username
Thu Feb 27 12:07:11 2014 : Debug: radius_xlat:
 '(&(sAMAccountname=username)(objectClass=user))'
Thu Feb 27 12:07:11 2014 : Debug: radius_xlat:
 'CN=USERS,DC=MYCOMPANY,DC=NET,DC=BR'
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: attempting LDAP reconnection
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: (re)connect to
myadserver.MYCOMPANY.net.br:389, authentication 0
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: bind as
CN=AUTHENTIC,CN=USERS,DC=MYCOMPANY,DC=NET,DC=BR/adpasswd to
myadserver.MYCOMPANY.net.br:389
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: waiting for bind result ...
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: Bind was successful
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: performing search in
CN=USERS,DC=MYCOMPANY,DC=NET,DC=BR, with filter
(&(sAMAccountname=username)(objectClass=user))
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: checking if remote access for
username is allowed by SamAccountName
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: looking for check items in
directory...
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: looking for reply items in
directory...
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: Setting Auth-Type = ldap
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: user username authorized to use
remote access
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: returned from
ldap (rlm_ldap) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modcall[authorize]: module "ldap"
returns ok for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: calling files
(rlm_files) for request 0
Thu Feb 27 12:07:11 2014 : Debug:     users: Matched entry DEFAULT at line 4
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: Entering ldap_groupcmp()
Thu Feb 27 12:07:11 2014 : Debug: radius_xlat:
 'CN=USERS,DC=MYCOMPANY,DC=NET,DC=BR'
Thu Feb 27 12:07:11 2014 : Debug: radius_xlat:
 '(&(objectClass=group)(member=CN\3dLUIS VEIGA
\28324278\29\2cCN\3dUsers\2cDC\3dMYCOMPANY\2cDC\3dnet\2cDC\3dbr))'
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: ldap_get_conn: Checking Id: 0
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: ldap_get_conn: Got Id: 0
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: performing search in
CN=USERS,DC=MYCOMPANY,DC=NET,DC=BR, with filter
(&(cn=sbcadmin)(&(objectClass=group)(member=CN\3dLUIS VEIGA
\28324278\29\2cCN\3dUsers\2cDC\3dMYCOMPANY\2cDC\3dnet\2cDC\3dbr)))
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap::ldap_groupcmp: User found in
group sbcadmin
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: ldap_release_conn: Release Id: 0
Thu Feb 27 12:07:11 2014 : Debug:     users: Matched entry DEFAULT at line 7
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authorize]: returned from
files (rlm_files) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modcall[authorize]: module "files"
returns ok for request 0
Thu Feb 27 12:07:11 2014 : Debug: modcall: leaving group authorize (returns
ok) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   rad_check_password:  Found Auth-Type
LDAP
Thu Feb 27 12:07:11 2014 : Debug: auth: type "LDAP"
Thu Feb 27 12:07:11 2014 : Debug:   Processing the authenticate section of
radiusd.conf
Thu Feb 27 12:07:11 2014 : Debug: modcall: entering group LDAP for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authenticate]: calling ldap
(rlm_ldap) for request 0
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: - authenticate
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: login attempt by "username"
with password "userpassword"
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: user DN: CN=LUIS VEIGA
(324278),CN=Users,DC=MYCOMPANY,DC=net,DC=br
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: (re)connect to
myadserver.MYCOMPANY.net.br:389, authentication 1
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: bind as CN=LUIS VEIGA
(324278),CN=Users,DC=MYCOMPANY,DC=net,DC=br/userpassword to
myadserver.MYCOMPANY.net.br:389
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: waiting for bind result ...
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: Bind was successful
Thu Feb 27 12:07:11 2014 : Debug: rlm_ldap: user username authenticated
succesfully
Thu Feb 27 12:07:11 2014 : Debug:   modsingle[authenticate]: returned from
ldap (rlm_ldap) for request 0
Thu Feb 27 12:07:11 2014 : Debug:   modcall[authenticate]: module "ldap"
returns ok for request 0
Thu Feb 27 12:07:11 2014 : Debug: modcall: leaving group LDAP (returns ok)
for request 0
Thu Feb 27 12:07:11 2014 : Auth: Login OK: [username/userpassword] (from
client myhost.spoig port 118751232)
Sending Access-Accept of id 157 to 10.253.7.156 port 1812
        Service-Type = Login-User
        Login-Service = Telnet
        Port-Limit := 5
        Idle-Timeout := 300
        Session-Timeout := 300
        Acme-User-Class := "Admin"
        Acme-User-Privilege := "sftpForAll"
Thu Feb 27 12:07:11 2014 : Debug: Finished request 0
Thu Feb 27 12:07:11 2014 : Debug: Going to the next request
Thu Feb 27 12:07:11 2014 : Debug: --- Walking the entire request list ---
Thu Feb 27 12:07:11 2014 : Debug: Waking up in 7 seconds...




2014-02-12 6:06 GMT-02:00 Alan Buxey <A.L.M.Buxey at lboro.ac.uk>:

> >I solve the problem with no version upgrade.
>
> Well. .. That's good...apart from that fact that 1.1.3 has several
> security problems some of which are remotely triggered and it has quite a
> few well known bugs. That is one reason you were helpfully advised to
> upgrade to at least the 2.x release! :/
>
>
> Alan
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20140227/f54628f1/attachment-0001.html>