Hello, first setup: FreeRADIUS Version 2.1.7, for host x86_64-pc-linux-gnu, built on Dec 10 2009 at 17:33:51 on Debian Lenny build via dpkg-buildpackage I have a question regarding this debug log output. I'm a bit confused about this logic operations and the boolean result: Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-4} -> 32933844 Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856 Sun Dec 20 15:44:46 2009 : Info: ? Evaluating ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") -> TRUE Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") -> TRUE Sun Dec 20 15:44:46 2009 : Info: ++- entering if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") {...} Sun Dec 20 15:44:46 2009 : Info: expand: USER %{User-Name}: hat Traffic-Limit erreicht! -> USER Stephan.Kirsten: hat Traffic-Limit erreicht! Sun Dec 20 15:44:46 2009 : Info: +++[reply] returns ok should obviously became false and won't expand Sun Dec 20 15:44:46 2009 : Info: ++- if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") returns ok Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" < "%{control:Tmp-Integer-5}") Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-4} -> 32933844 Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856 Sun Dec 20 15:44:46 2009 : Info: ? Evaluating ("%{control:Tmp-Integer-4}" < "%{control:Tmp-Integer-5}") -> FALSE Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" < "%{control:Tmp-Integer-5}") -> FALSE should be true and expanded So how does this come together? The debug log is attached to this mail. I hope someone ca clarify this problem -Stephan Sun Dec 20 15:44:03 2009 : Info: FreeRADIUS Version 2.1.7, for host x86_64-pc-linux-gnu, built on Dec 10 2009 at 17:33:51 Sun Dec 20 15:44:03 2009 : Info: Copyright (C) 1999-2009 The FreeRADIUS server project and contributors. Sun Dec 20 15:44:03 2009 : Info: There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A Sun Dec 20 15:44:03 2009 : Info: PARTICULAR PURPOSE. Sun Dec 20 15:44:03 2009 : Info: You may redistribute copies of FreeRADIUS under the terms of the Sun Dec 20 15:44:03 2009 : Info: GNU General Public License v2. Sun Dec 20 15:44:03 2009 : Info: Starting - reading configuration files ... Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/radiusd.conf Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/proxy.conf Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/clients.conf Sun Dec 20 15:44:03 2009 : Debug: including files in directory /etc/freeradius/modules/ Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/sradutmp Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/detail Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/expiration Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/smsotp Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/otp Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/expr Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/mschap Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/digest Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/pap Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/cui Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/sqlcounter_expire_on_login Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/ldap Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/wimax Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/preprocess Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/mac2ip Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/counter Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/always Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/exec Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/echo Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/attr_rewrite Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/mac2vlan Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/etc_group Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/detail.example.com Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/realm Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/detail.log Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/unix Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/perl Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/linelog Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/sql_log Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/chap Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/inner-eap Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/krb5 Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/radutmp Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/smbpasswd Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/policy Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/acct_unique Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/passwd Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/logintime Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/files Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/checkval Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/ippool Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/pam Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/modules/attr_filter Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/eap.conf Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/sql.conf Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/sql/mysql/dialup.conf Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/policy.conf Sun Dec 20 15:44:03 2009 : Debug: including files in directory /etc/freeradius/sites-enabled/ Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/sites-enabled/eap Sun Dec 20 15:44:03 2009 : Debug: including configuration file /etc/freeradius/sites-enabled/pptp Sun Dec 20 15:44:03 2009 : Debug: group = freerad Sun Dec 20 15:44:03 2009 : Debug: user = freerad Sun Dec 20 15:44:03 2009 : Debug: including dictionary file /etc/freeradius/dictionary Sun Dec 20 15:44:03 2009 : Debug: main { Sun Dec 20 15:44:03 2009 : Debug: prefix = "/usr" Sun Dec 20 15:44:03 2009 : Debug: localstatedir = "/var" Sun Dec 20 15:44:03 2009 : Debug: logdir = "/var/log/freeradius" Sun Dec 20 15:44:03 2009 : Debug: libdir = "/usr/lib/freeradius" Sun Dec 20 15:44:03 2009 : Debug: radacctdir = "/var/log/freeradius/radacct" Sun Dec 20 15:44:03 2009 : Debug: hostname_lookups = no Sun Dec 20 15:44:03 2009 : Debug: max_request_time = 30 Sun Dec 20 15:44:03 2009 : Debug: cleanup_delay = 5 Sun Dec 20 15:44:03 2009 : Debug: max_requests = 1024 Sun Dec 20 15:44:03 2009 : Debug: allow_core_dumps = no Sun Dec 20 15:44:03 2009 : Debug: pidfile = "/var/run/freeradius/freeradius.pid" Sun Dec 20 15:44:03 2009 : Debug: checkrad = "/usr/sbin/checkrad" Sun Dec 20 15:44:03 2009 : Debug: debug_level = 0 Sun Dec 20 15:44:03 2009 : Debug: proxy_requests = yes Sun Dec 20 15:44:03 2009 : Debug: log { Sun Dec 20 15:44:03 2009 : Debug: stripped_names = no Sun Dec 20 15:44:03 2009 : Debug: auth = no Sun Dec 20 15:44:03 2009 : Debug: auth_badpass = no Sun Dec 20 15:44:03 2009 : Debug: auth_goodpass = no Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: security { Sun Dec 20 15:44:03 2009 : Debug: max_attributes = 200 Sun Dec 20 15:44:03 2009 : Debug: reject_delay = 1 Sun Dec 20 15:44:03 2009 : Debug: status_server = yes Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: radiusd: #### Loading Realms and Home Servers #### Sun Dec 20 15:44:03 2009 : Debug: proxy server { Sun Dec 20 15:44:03 2009 : Debug: retry_delay = 5 Sun Dec 20 15:44:03 2009 : Debug: retry_count = 3 Sun Dec 20 15:44:03 2009 : Debug: default_fallback = no Sun Dec 20 15:44:03 2009 : Debug: dead_time = 120 Sun Dec 20 15:44:03 2009 : Debug: wake_all_if_all_dead = no Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: home_server localhost { Sun Dec 20 15:44:03 2009 : Debug: ipaddr = 127.0.0.1 Sun Dec 20 15:44:03 2009 : Debug: port = 1812 Sun Dec 20 15:44:03 2009 : Debug: type = "auth" Sun Dec 20 15:44:03 2009 : Debug: secret = "testing123" Sun Dec 20 15:44:03 2009 : Debug: response_window = 20 Sun Dec 20 15:44:03 2009 : Debug: max_outstanding = 65536 Sun Dec 20 15:44:03 2009 : Debug: require_message_authenticator = no Sun Dec 20 15:44:03 2009 : Debug: zombie_period = 40 Sun Dec 20 15:44:03 2009 : Debug: status_check = "status-server" Sun Dec 20 15:44:03 2009 : Debug: ping_interval = 30 Sun Dec 20 15:44:03 2009 : Debug: check_interval = 30 Sun Dec 20 15:44:03 2009 : Debug: num_answers_to_alive = 3 Sun Dec 20 15:44:03 2009 : Debug: num_pings_to_alive = 3 Sun Dec 20 15:44:03 2009 : Debug: revive_interval = 120 Sun Dec 20 15:44:03 2009 : Debug: status_check_timeout = 4 Sun Dec 20 15:44:03 2009 : Debug: irt = 2 Sun Dec 20 15:44:03 2009 : Debug: mrt = 16 Sun Dec 20 15:44:03 2009 : Debug: mrc = 5 Sun Dec 20 15:44:03 2009 : Debug: mrd = 30 Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: home_server_pool my_auth_failover { Sun Dec 20 15:44:03 2009 : Debug: type = fail-over Sun Dec 20 15:44:03 2009 : Debug: home_server = localhost Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: realm example.com { Sun Dec 20 15:44:03 2009 : Debug: auth_pool = my_auth_failover Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: realm LOCAL { Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: radiusd: #### Loading Clients #### Sun Dec 20 15:44:03 2009 : Debug: client localhost { Sun Dec 20 15:44:03 2009 : Debug: ipaddr = 127.0.0.1 Sun Dec 20 15:44:03 2009 : Debug: require_message_authenticator = no Sun Dec 20 15:44:03 2009 : Debug: secret = "testing123" Sun Dec 20 15:44:03 2009 : Debug: nastype = "other" Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: client 10.17.2.0/24 { Sun Dec 20 15:44:03 2009 : Debug: require_message_authenticator = no Sun Dec 20 15:44:03 2009 : Debug: secret = "testing123" Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: client 192.168.0.0/16 { Sun Dec 20 15:44:03 2009 : Debug: require_message_authenticator = no Sun Dec 20 15:44:03 2009 : Debug: secret = "test" Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: radiusd: #### Instantiating modules #### Sun Dec 20 15:44:03 2009 : Debug: instantiate { Sun Dec 20 15:44:03 2009 : Debug: (Loaded rlm_exec, checking if it's valid) Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to module rlm_exec Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating exec Sun Dec 20 15:44:03 2009 : Debug: exec { Sun Dec 20 15:44:03 2009 : Debug: wait = no Sun Dec 20 15:44:03 2009 : Debug: input_pairs = "request" Sun Dec 20 15:44:03 2009 : Debug: shell_escape = yes Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: (Loaded rlm_expr, checking if it's valid) Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to module rlm_expr Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating expr Sun Dec 20 15:44:03 2009 : Debug: (Loaded rlm_expiration, checking if it's valid) Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to module rlm_expiration Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating expiration Sun Dec 20 15:44:03 2009 : Debug: expiration { Sun Dec 20 15:44:03 2009 : Debug: reply-message = "Password Has Expired " Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: (Loaded rlm_logintime, checking if it's valid) Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to module rlm_logintime Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating logintime Sun Dec 20 15:44:03 2009 : Debug: logintime { Sun Dec 20 15:44:03 2009 : Debug: reply-message = "You are calling outside your allowed timespan " Sun Dec 20 15:44:03 2009 : Debug: minimum-timeout = 60 Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: radiusd: #### Loading Virtual Servers #### Sun Dec 20 15:44:03 2009 : Debug: server eap { Sun Dec 20 15:44:03 2009 : Debug: modules { Sun Dec 20 15:44:03 2009 : Debug: Module: Checking authenticate {...} for more modules to load Sun Dec 20 15:44:03 2009 : Debug: (Loaded rlm_mschap, checking if it's valid) Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to module rlm_mschap Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating mschap Sun Dec 20 15:44:03 2009 : Debug: mschap { Sun Dec 20 15:44:03 2009 : Debug: use_mppe = yes Sun Dec 20 15:44:03 2009 : Debug: require_encryption = no Sun Dec 20 15:44:03 2009 : Debug: require_strong = no Sun Dec 20 15:44:03 2009 : Debug: with_ntdomain_hack = no Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: (Loaded rlm_eap, checking if it's valid) Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to module rlm_eap Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating eap Sun Dec 20 15:44:03 2009 : Debug: eap { Sun Dec 20 15:44:03 2009 : Debug: default_eap_type = "peap" Sun Dec 20 15:44:03 2009 : Debug: timer_expire = 60 Sun Dec 20 15:44:03 2009 : Debug: ignore_unknown_eap_types = no Sun Dec 20 15:44:03 2009 : Debug: cisco_accounting_username_bug = no Sun Dec 20 15:44:03 2009 : Debug: max_sessions = 2048 Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to sub-module rlm_eap_md5 Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating eap-md5 Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to sub-module rlm_eap_leap Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating eap-leap Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to sub-module rlm_eap_gtc Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating eap-gtc Sun Dec 20 15:44:03 2009 : Debug: gtc { Sun Dec 20 15:44:03 2009 : Debug: challenge = "Password: " Sun Dec 20 15:44:03 2009 : Debug: auth_type = "PAP" Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to sub-module rlm_eap_tls Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating eap-tls Sun Dec 20 15:44:03 2009 : Debug: tls { Sun Dec 20 15:44:03 2009 : Debug: rsa_key_exchange = no Sun Dec 20 15:44:03 2009 : Debug: dh_key_exchange = yes Sun Dec 20 15:44:03 2009 : Debug: rsa_key_length = 512 Sun Dec 20 15:44:03 2009 : Debug: dh_key_length = 512 Sun Dec 20 15:44:03 2009 : Debug: verify_depth = 0 Sun Dec 20 15:44:03 2009 : Debug: pem_file_type = yes Sun Dec 20 15:44:03 2009 : Debug: private_key_file = "/etc/freeradius/certs/server.pem" Sun Dec 20 15:44:03 2009 : Debug: certificate_file = "/etc/freeradius/certs/server.pem" Sun Dec 20 15:44:03 2009 : Debug: CA_file = "/etc/freeradius/certs/ca.pem" Sun Dec 20 15:44:03 2009 : Debug: private_key_password = "whatever" Sun Dec 20 15:44:03 2009 : Debug: dh_file = "/etc/freeradius/certs/dh" Sun Dec 20 15:44:03 2009 : Debug: random_file = "/etc/freeradius/certs/random" Sun Dec 20 15:44:03 2009 : Debug: fragment_size = 1024 Sun Dec 20 15:44:03 2009 : Debug: include_length = yes Sun Dec 20 15:44:03 2009 : Debug: check_crl = no Sun Dec 20 15:44:03 2009 : Debug: cipher_list = "DEFAULT" Sun Dec 20 15:44:03 2009 : Debug: make_cert_command = "/etc/freeradius/certs/bootstrap" Sun Dec 20 15:44:03 2009 : Debug: cache { Sun Dec 20 15:44:03 2009 : Debug: enable = no Sun Dec 20 15:44:03 2009 : Debug: lifetime = 24 Sun Dec 20 15:44:03 2009 : Debug: max_entries = 255 Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to sub-module rlm_eap_peap Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating eap-peap Sun Dec 20 15:44:03 2009 : Debug: peap { Sun Dec 20 15:44:03 2009 : Debug: default_eap_type = "md5" Sun Dec 20 15:44:03 2009 : Debug: copy_request_to_tunnel = no Sun Dec 20 15:44:03 2009 : Debug: use_tunneled_reply = no Sun Dec 20 15:44:03 2009 : Debug: proxy_tunneled_request_as_eap = yes Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to sub-module rlm_eap_mschapv2 Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating eap-mschapv2 Sun Dec 20 15:44:03 2009 : Debug: mschapv2 { Sun Dec 20 15:44:03 2009 : Debug: with_ntdomain_hack = no Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: Module: Checking authorize {...} for more modules to load Sun Dec 20 15:44:03 2009 : Debug: (Loaded rlm_sql, checking if it's valid) Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to module rlm_sql Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating sql Sun Dec 20 15:44:03 2009 : Debug: sql { Sun Dec 20 15:44:03 2009 : Debug: driver = "rlm_sql_mysql" Sun Dec 20 15:44:03 2009 : Debug: server = "athene.fbn-dd.de" Sun Dec 20 15:44:03 2009 : Debug: port = "" Sun Dec 20 15:44:03 2009 : Debug: login = "radius" Sun Dec 20 15:44:03 2009 : Debug: password = "radius" Sun Dec 20 15:44:03 2009 : Debug: radius_db = "radius" Sun Dec 20 15:44:03 2009 : Debug: read_groups = yes Sun Dec 20 15:44:03 2009 : Debug: sqltrace = no Sun Dec 20 15:44:03 2009 : Debug: sqltracefile = "/var/log/freeradius/sqltrace.sql" Sun Dec 20 15:44:03 2009 : Debug: readclients = no Sun Dec 20 15:44:03 2009 : Debug: deletestalesessions = yes Sun Dec 20 15:44:03 2009 : Debug: num_sql_socks = 5 Sun Dec 20 15:44:03 2009 : Debug: lifetime = 0 Sun Dec 20 15:44:03 2009 : Debug: max_queries = 0 Sun Dec 20 15:44:03 2009 : Debug: sql_user_name = "%{User-Name}" Sun Dec 20 15:44:03 2009 : Debug: default_user_profile = "" Sun Dec 20 15:44:03 2009 : Debug: nas_query = "SELECT id, nasname, shortname, type, secret FROM nas" Sun Dec 20 15:44:03 2009 : Debug: authorize_check_query = "SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id" Sun Dec 20 15:44:03 2009 : Debug: authorize_reply_query = "SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id" Sun Dec 20 15:44:03 2009 : Debug: authorize_group_check_query = "SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id" Sun Dec 20 15:44:03 2009 : Debug: authorize_group_reply_query = "SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id" Sun Dec 20 15:44:03 2009 : Debug: accounting_onoff_query = " UPDATE radacct SET acctstoptime = '%S', acctsessiontime = unix_timestamp('%S') - unix_timestamp(acctstarttime), acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = %{%{Acct-Delay-Time}:-0} WHERE acctstoptime IS NULL AND nasipaddress = '%{NAS-IP-Address}' AND acctstarttime <= '%S'" Sun Dec 20 15:44:03 2009 : Debug: accounting_update_query = " UPDATE radacct SET framedipaddress = '%{Framed-IP-Address}', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Sun Dec 20 15:44:03 2009 : Debug: accounting_update_query_alt = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctsessiontime, acctauthentic, connectinfo_start, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, servicetype, framedprotocol, framedipaddress, acctstartdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{%{Acct-Session-Time}:-0} + %{%{Acct-Delay-Time}:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{X-Ascend-Session-Svr-Key}')" Sun Dec 20 15:44:03 2009 : Debug: accounting_start_query = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '%{%{Acct-Delay-Time}:-0}', '0', '%{X-Ascend-Session-Svr-Key}')" Sun Dec 20 15:44:03 2009 : Debug: accounting_start_query_alt = " UPDATE radacct SET acctstarttime = '%S', acctstartdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_start = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Sun Dec 20 15:44:03 2009 : Debug: accounting_stop_query = " UPDATE radacct SET acctstoptime = '%S', acctsessiontime = '%{Acct-Session-Time}', acctinputoctets = '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', acctoutputoctets = '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', acctterminatecause = '%{Acct-Terminate-Cause}', acctstopdelay = '%{%{Acct-Delay-Time}:-0}', connectinfo_stop = '%{Connect-Info}' WHERE acctsessionid = '%{Acct-Session-Id}' AND username = '%{SQL-User-Name}' AND nasipaddress = '%{NAS-IP-Address}'" Sun Dec 20 15:44:03 2009 : Debug: accounting_stop_query_alt = " INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctstartdelay, acctstopdelay) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{%{Acct-Session-Time}:-0} + %{%{Acct-Delay-Time}:-0}) SECOND), '%S', '%{Acct-Session-Time}', '%{Acct-Authentic}', '', '%{Connect-Info}', '%{%{Acct-Input-Gigawords}:-0}' << 32 | '%{%{Acct-Input-Octets}:-0}', '%{%{Acct-Output-Gigawords}:-0}' << 32 | '%{%{Acct-Output-Octets}:-0}', '%{Called-Station-Id}', '%{Calling-Station-Id}', '%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}', '0', '%{%{Acct-Delay-Time}:-0}')" Sun Dec 20 15:44:03 2009 : Debug: group_membership_query = "SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority" Sun Dec 20 15:44:03 2009 : Debug: connect_failure_retry_delay = 60 Sun Dec 20 15:44:03 2009 : Debug: simul_count_query = "" Sun Dec 20 15:44:03 2009 : Debug: simul_verify_query = "SELECT radacctid, acctsessionid, username, nasipaddress, nasportid, framedipaddress, callingstationid, framedprotocol FROM radacct WHERE username = '%{SQL-User-Name}' AND acctstoptime IS NULL" Sun Dec 20 15:44:03 2009 : Debug: postauth_query = "INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')" Sun Dec 20 15:44:03 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Sun Dec 20 15:44:03 2009 : Info: rlm_sql (sql): Attempting to connect to radius@athene.fbn-dd.de:/radius Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): starting 0 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0 Sun Dec 20 15:44:03 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): Connected new DB handle, #0 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): starting 1 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #1 Sun Dec 20 15:44:03 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): Connected new DB handle, #1 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): starting 2 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #2 Sun Dec 20 15:44:03 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): Connected new DB handle, #2 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): starting 3 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #3 Sun Dec 20 15:44:03 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): Connected new DB handle, #3 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): starting 4 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): Attempting to connect rlm_sql_mysql #4 Sun Dec 20 15:44:03 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql): Connected new DB handle, #4 Sun Dec 20 15:44:03 2009 : Debug: Module: Checking accounting {...} for more modules to load Sun Dec 20 15:44:03 2009 : Debug: (Loaded rlm_acct_unique, checking if it's valid) Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to module rlm_acct_unique Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating acct_unique Sun Dec 20 15:44:03 2009 : Debug: acct_unique { Sun Dec 20 15:44:03 2009 : Debug: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: (Loaded rlm_detail, checking if it's valid) Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to module rlm_detail Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating detail Sun Dec 20 15:44:03 2009 : Debug: detail { Sun Dec 20 15:44:03 2009 : Debug: detailfile = "/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d" Sun Dec 20 15:44:03 2009 : Debug: header = "%t" Sun Dec 20 15:44:03 2009 : Debug: detailperm = 384 Sun Dec 20 15:44:03 2009 : Debug: dirperm = 493 Sun Dec 20 15:44:03 2009 : Debug: locking = no Sun Dec 20 15:44:03 2009 : Debug: log_packet_header = no Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: Module: Checking session {...} for more modules to load Sun Dec 20 15:44:03 2009 : Debug: Module: Checking post-auth {...} for more modules to load Sun Dec 20 15:44:03 2009 : Debug: } # modules Sun Dec 20 15:44:03 2009 : Debug: } # server Sun Dec 20 15:44:03 2009 : Debug: server pptp { Sun Dec 20 15:44:03 2009 : Debug: modules { Sun Dec 20 15:44:03 2009 : Debug: Module: Checking authenticate {...} for more modules to load Sun Dec 20 15:44:03 2009 : Debug: Module: Checking authorize {...} for more modules to load Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating sql_mitglieder Sun Dec 20 15:44:03 2009 : Debug: sql sql_mitglieder { Sun Dec 20 15:44:03 2009 : Debug: driver = "rlm_sql_mysql" Sun Dec 20 15:44:03 2009 : Debug: server = "dbserver.fbn-dd.de" Sun Dec 20 15:44:03 2009 : Debug: port = "" Sun Dec 20 15:44:03 2009 : Debug: login = "radius_server" Sun Dec 20 15:44:03 2009 : Debug: password = "r4d1u5" Sun Dec 20 15:44:03 2009 : Debug: radius_db = "users" Sun Dec 20 15:44:03 2009 : Debug: read_groups = yes Sun Dec 20 15:44:03 2009 : Debug: sqltrace = no Sun Dec 20 15:44:03 2009 : Debug: sqltracefile = "/var/log/freeradius/sqltrace.sql" Sun Dec 20 15:44:03 2009 : Debug: readclients = no Sun Dec 20 15:44:03 2009 : Debug: deletestalesessions = yes Sun Dec 20 15:44:03 2009 : Debug: num_sql_socks = 5 Sun Dec 20 15:44:03 2009 : Debug: lifetime = 0 Sun Dec 20 15:44:03 2009 : Debug: max_queries = 0 Sun Dec 20 15:44:03 2009 : Debug: sql_user_name = "%{User-Name}" Sun Dec 20 15:44:03 2009 : Debug: default_user_profile = "" Sun Dec 20 15:44:03 2009 : Debug: nas_query = "SELECT id,nasname,shortname,type,secret FROM nas" Sun Dec 20 15:44:03 2009 : Debug: authorize_check_query = " SELECT BNID as id, Username as username, 'Cleartext-Password' as attribute, Password as value , ':=' as op FROM Mitglieder WHERE Username = '%{SQL-User-Name}' AND VPN_IO = 1 AND Status BETWEEN 1600 AND 8900" Sun Dec 20 15:44:03 2009 : Debug: authorize_group_check_query = "" Sun Dec 20 15:44:03 2009 : Debug: authorize_group_reply_query = "" Sun Dec 20 15:44:03 2009 : Debug: accounting_onoff_query = "" Sun Dec 20 15:44:03 2009 : Debug: accounting_update_query = "" Sun Dec 20 15:44:03 2009 : Debug: accounting_update_query_alt = "" Sun Dec 20 15:44:03 2009 : Debug: accounting_start_query = "" Sun Dec 20 15:44:03 2009 : Debug: accounting_start_query_alt = "" Sun Dec 20 15:44:03 2009 : Debug: accounting_stop_query = "" Sun Dec 20 15:44:03 2009 : Debug: accounting_stop_query_alt = "" Sun Dec 20 15:44:03 2009 : Debug: connect_failure_retry_delay = 60 Sun Dec 20 15:44:03 2009 : Debug: simul_count_query = "" Sun Dec 20 15:44:03 2009 : Debug: simul_verify_query = "" Sun Dec 20 15:44:03 2009 : Debug: postauth_query = "" Sun Dec 20 15:44:03 2009 : Debug: safe-characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Info: rlm_sql (sql_mitglieder): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked Sun Dec 20 15:44:03 2009 : Info: rlm_sql (sql_mitglieder): Attempting to connect to radius_server@dbserver.fbn-dd.de:/users Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): starting 0 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): Attempting to connect rlm_sql_mysql #0 Sun Dec 20 15:44:03 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #0 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): Connected new DB handle, #0 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): starting 1 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): Attempting to connect rlm_sql_mysql #1 Sun Dec 20 15:44:03 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #1 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): Connected new DB handle, #1 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): starting 2 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): Attempting to connect rlm_sql_mysql #2 Sun Dec 20 15:44:03 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #2 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): Connected new DB handle, #2 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): starting 3 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): Attempting to connect rlm_sql_mysql #3 Sun Dec 20 15:44:03 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #3 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): Connected new DB handle, #3 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): starting 4 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): Attempting to connect rlm_sql_mysql #4 Sun Dec 20 15:44:03 2009 : Info: rlm_sql_mysql: Starting connect to MySQL server for #4 Sun Dec 20 15:44:03 2009 : Debug: rlm_sql (sql_mitglieder): Connected new DB handle, #4 Sun Dec 20 15:44:03 2009 : Debug: (Loaded rlm_always, checking if it's valid) Sun Dec 20 15:44:03 2009 : Debug: Module: Linked to module rlm_always Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating reject Sun Dec 20 15:44:03 2009 : Debug: always reject { Sun Dec 20 15:44:03 2009 : Debug: rcode = "reject" Sun Dec 20 15:44:03 2009 : Debug: simulcount = 0 Sun Dec 20 15:44:03 2009 : Debug: mpp = no Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: Module: Checking accounting {...} for more modules to load Sun Dec 20 15:44:03 2009 : Debug: Module: Instantiating echo Sun Dec 20 15:44:03 2009 : Debug: exec echo { Sun Dec 20 15:44:03 2009 : Debug: wait = yes Sun Dec 20 15:44:03 2009 : Debug: program = "/bin/echo %{User-Name}" Sun Dec 20 15:44:03 2009 : Debug: input_pairs = "request" Sun Dec 20 15:44:03 2009 : Debug: output_pairs = "reply" Sun Dec 20 15:44:03 2009 : Debug: shell_escape = yes Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: Module: Checking session {...} for more modules to load Sun Dec 20 15:44:03 2009 : Debug: Module: Checking post-auth {...} for more modules to load Sun Dec 20 15:44:03 2009 : Debug: } # modules Sun Dec 20 15:44:03 2009 : Debug: } # server Sun Dec 20 15:44:03 2009 : Debug: server { Sun Dec 20 15:44:03 2009 : Debug: modules { Sun Dec 20 15:44:03 2009 : Debug: } # modules Sun Dec 20 15:44:03 2009 : Debug: } # server Sun Dec 20 15:44:03 2009 : Debug: radiusd: #### Opening IP addresses and Ports #### Sun Dec 20 15:44:03 2009 : Debug: listen { Sun Dec 20 15:44:03 2009 : Debug: type = "auth" Sun Dec 20 15:44:03 2009 : Debug: ipaddr = * Sun Dec 20 15:44:03 2009 : Debug: port = 1812 Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: listen { Sun Dec 20 15:44:03 2009 : Debug: type = "auth" Sun Dec 20 15:44:03 2009 : Debug: ipaddr = * Sun Dec 20 15:44:03 2009 : Debug: port = 1860 Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: listen { Sun Dec 20 15:44:03 2009 : Debug: type = "acct" Sun Dec 20 15:44:03 2009 : Debug: ipaddr = * Sun Dec 20 15:44:03 2009 : Debug: port = 1861 Sun Dec 20 15:44:03 2009 : Debug: } Sun Dec 20 15:44:03 2009 : Debug: Listening on authentication address * port 1812 as server eap Sun Dec 20 15:44:03 2009 : Debug: Listening on authentication address * port 1860 as server pptp Sun Dec 20 15:44:03 2009 : Debug: Listening on accounting address * port 1861 as server pptp Sun Dec 20 15:44:03 2009 : Debug: Listening on proxy address * port 1814 Sun Dec 20 15:44:03 2009 : Debug: Ready to process requests. rad_recv: Access-Request packet from host 192.168.254.20 port 43443, id=34, length=185 Service-Type = Framed-User Framed-Protocol = PPP NAS-Port = 27 NAS-Port-Type = Virtual User-Name = "Stephan.Kirsten" Calling-Station-Id = "10.17.2.2" Called-Station-Id = "192.168.254.20" MS-CHAP-Challenge = 0x6af23287e589a4d403e5e4ff5b327de1 MS-CHAP2-Response = 0x0100f2a949c8f48c5887c6ec6eaaba0e2afc0000000000000000ef8a3b845bd4b84e1322a794860bcbf5b5785fd6b0d9a37f NAS-Identifier = "Test-ES" NAS-IP-Address = 192.168.254.20 Sun Dec 20 15:44:46 2009 : Info: server pptp { Sun Dec 20 15:44:46 2009 : Info: +- entering group authorize {...} Sun Dec 20 15:44:46 2009 : Info: sql_xlat Sun Dec 20 15:44:46 2009 : Info: expand: %{User-Name} -> Stephan.Kirsten Sun Dec 20 15:44:46 2009 : Info: sql_set_user escaped user --> 'Stephan.Kirsten' Sun Dec 20 15:44:46 2009 : Info: expand: SELECT Sperre FROM Mitglieder WHERE Username = '%{User-Name}' AND Status BETWEEN 1600 AND 8900 -> SELECT Sperre FROM Mitglieder WHERE Username = 'Stephan.Kirsten' AND Status BETWEEN 1600 AND 8900 Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql_mitglieder): Reserving sql socket id: 4 Sun Dec 20 15:44:46 2009 : Info: sql_xlat finished Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql_mitglieder): Released sql socket id: 4 Sun Dec 20 15:44:46 2009 : Info: expand: %{sql_mitglieder:SELECT Sperre FROM Mitglieder WHERE Username = '%{User-Name}' AND Status BETWEEN 1600 AND 8900} -> 0 Sun Dec 20 15:44:46 2009 : Info: sql_xlat Sun Dec 20 15:44:46 2009 : Info: expand: %{User-Name} -> Stephan.Kirsten Sun Dec 20 15:44:46 2009 : Info: sql_set_user escaped user --> 'Stephan.Kirsten' Sun Dec 20 15:44:46 2009 : Info: expand: SELECT count(UserName) From radacct Where UNIX_TIMESTAMP(AcctStopTime)='0' AND Username='%{User-Name}' AND UNIX_TIMESTAMP(AcctStartTime)+AcctSessionTime > UNIX_TIMESTAMP(DATE_SUB( now(),INTERVAL 600 SECOND)) Group By Username -> SELECT count(UserName) From radacct Where UNIX_TIMESTAMP(AcctStopTime)='0' AND Username='Stephan.Kirsten' AND UNIX_TIMESTAMP(AcctStartTime)+AcctSessionTime > UNIX_TIMESTAMP(DATE_SUB( now(),INTERVAL 600 SECOND)) Group By Username Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 4 Sun Dec 20 15:44:46 2009 : Info: SQL query did not return any results Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql): Released sql socket id: 4 Sun Dec 20 15:44:46 2009 : Info: expand: %{sql:SELECT count(UserName) From radacct Where UNIX_TIMESTAMP(AcctStopTime)='0' AND Username='%{User-Name}' AND UNIX_TIMESTAMP(AcctStartTime)+AcctSessionTime > UNIX_TIMESTAMP(DATE_SUB( now(),INTERVAL 600 SECOND)) Group By Username} -> Sun Dec 20 15:44:46 2009 : Info: sql_xlat Sun Dec 20 15:44:46 2009 : Info: expand: %{User-Name} -> Stephan.Kirsten Sun Dec 20 15:44:46 2009 : Info: sql_set_user escaped user --> 'Stephan.Kirsten' Sun Dec 20 15:44:46 2009 : Info: expand: SELECT VPN_IO FROM Mitglieder Where Username = '%{User-Name}' AND Status BETWEEN 1600 AND 8900 -> SELECT VPN_IO FROM Mitglieder Where Username = 'Stephan.Kirsten' AND Status BETWEEN 1600 AND 8900 Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql_mitglieder): Reserving sql socket id: 3 Sun Dec 20 15:44:46 2009 : Info: sql_xlat finished Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql_mitglieder): Released sql socket id: 3 Sun Dec 20 15:44:46 2009 : Info: expand: %{sql_mitglieder:SELECT VPN_IO FROM Mitglieder Where Username = '%{User-Name}' AND Status BETWEEN 1600 AND 8900} -> 1 Sun Dec 20 15:44:46 2009 : Info: sql_xlat Sun Dec 20 15:44:46 2009 : Info: expand: %{User-Name} -> Stephan.Kirsten Sun Dec 20 15:44:46 2009 : Info: sql_set_user escaped user --> 'Stephan.Kirsten' Sun Dec 20 15:44:46 2009 : Info: expand: SELECT ROUND(SUM(AcctOutputOctets+AcctInputOctets)) FROM radacct WHERE Username='%{User-Name}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > UNIX_TIMESTAMP(DATE_SUB(now(), INTERVAL 7 DAY)) -> SELECT ROUND(SUM(AcctOutputOctets+AcctInputOctets)) FROM radacct WHERE Username='Stephan.Kirsten' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > UNIX_TIMESTAMP(DATE_SUB(now(), INTERVAL 7 DAY)) Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 3 Sun Dec 20 15:44:46 2009 : Info: sql_xlat finished Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql): Released sql socket id: 3 Sun Dec 20 15:44:46 2009 : Info: expand: %{sql:SELECT ROUND(SUM(AcctOutputOctets+AcctInputOctets)) FROM radacct WHERE Username='%{User-Name}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > UNIX_TIMESTAMP(DATE_SUB(now(), INTERVAL 7 DAY))} -> 32933844 Sun Dec 20 15:44:46 2009 : Info: sql_xlat Sun Dec 20 15:44:46 2009 : Info: expand: %{User-Name} -> Stephan.Kirsten Sun Dec 20 15:44:46 2009 : Info: sql_set_user escaped user --> 'Stephan.Kirsten' Sun Dec 20 15:44:46 2009 : Info: expand: SELECT TrafficPunkteMax*1024*1024 FROM Mitglieder WHERE Username = '%{User-Name}' AND Status BETWEEN 1600 AND 8900 -> SELECT TrafficPunkteMax*1024*1024 FROM Mitglieder WHERE Username = 'Stephan.Kirsten' AND Status BETWEEN 1600 AND 8900 Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql_mitglieder): Reserving sql socket id: 2 Sun Dec 20 15:44:46 2009 : Info: sql_xlat finished Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql_mitglieder): Released sql socket id: 2 Sun Dec 20 15:44:46 2009 : Info: expand: %{sql_mitglieder:SELECT TrafficPunkteMax*1024*1024 FROM Mitglieder WHERE Username = '%{User-Name}' AND Status BETWEEN 1600 AND 8900} -> 62914560000 Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} - %{control:Tmp-Integer-4} -> - Sun Dec 20 15:44:46 2009 : Info: expand: %{expr: %{control:Tmp-Integer-5} - %{control:Tmp-Integer-4} } -> 0 Sun Dec 20 15:44:46 2009 : Info: ++[control] returns notfound Sun Dec 20 15:44:46 2009 : Info: [mschap] Found MS-CHAP attributes. Setting 'Auth-Type = mschap' Sun Dec 20 15:44:46 2009 : Info: ++[mschap] returns ok Sun Dec 20 15:44:46 2009 : Info: [sql_mitglieder] expand: %{User-Name} -> Stephan.Kirsten Sun Dec 20 15:44:46 2009 : Info: [sql_mitglieder] sql_set_user escaped user --> 'Stephan.Kirsten' Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql_mitglieder): Reserving sql socket id: 1 Sun Dec 20 15:44:46 2009 : Info: [sql_mitglieder] expand: SELECT BNID as id, Username as username, 'Cleartext-Password' as attribute, Password as value , ':=' as op FROM Mitglieder WHERE Username = '%{SQL-User-Name}' AND VPN_IO = 1 AND Status BETWEEN 1600 AND 8900 -> SELECT BNID as id, Username as username, 'Cleartext-Password' as attribute, Password as value , ':=' as op FROM Mitglieder WHERE Username = 'Stephan.Kirsten' AND VPN_IO = 1 AND Status BETWEEN 1600 AND 8900 Sun Dec 20 15:44:46 2009 : Info: [sql_mitglieder] User found in radcheck table Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql_mitglieder): Released sql socket id: 1 Sun Dec 20 15:44:46 2009 : Info: ++[sql_mitglieder] returns ok Sun Dec 20 15:44:46 2009 : Info: ++? if (control:Tmp-Integer-1 > 0) Sun Dec 20 15:44:46 2009 : Info: ? Evaluating (control:Tmp-Integer-1 > 0) -> FALSE Sun Dec 20 15:44:46 2009 : Info: ++? if (control:Tmp-Integer-1 > 0) -> FALSE Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-2}" > "%{control:Tmp-Integer-3}") Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-2} -> 0 Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-3} -> 1 Sun Dec 20 15:44:46 2009 : Info: ? Evaluating ("%{control:Tmp-Integer-2}" > "%{control:Tmp-Integer-3}") -> FALSE Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-2}" > "%{control:Tmp-Integer-3}") -> FALSE Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-5}" == 0) Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856 Sun Dec 20 15:44:46 2009 : Info: ? Evaluating ("%{control:Tmp-Integer-5}" == 0) -> FALSE Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-5}" == 0) -> FALSE Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-4} -> 32933844 Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856 Sun Dec 20 15:44:46 2009 : Info: ? Evaluating ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") -> TRUE Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") -> TRUE Sun Dec 20 15:44:46 2009 : Info: ++- entering if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") {...} Sun Dec 20 15:44:46 2009 : Info: expand: USER %{User-Name}: hat Traffic-Limit erreicht! -> USER Stephan.Kirsten: hat Traffic-Limit erreicht! Sun Dec 20 15:44:46 2009 : Info: +++[reply] returns ok Sun Dec 20 15:44:46 2009 : Info: ++- if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") returns ok Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" < "%{control:Tmp-Integer-5}") Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-4} -> 32933844 Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856 Sun Dec 20 15:44:46 2009 : Info: ? Evaluating ("%{control:Tmp-Integer-4}" < "%{control:Tmp-Integer-5}") -> FALSE Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" < "%{control:Tmp-Integer-5}") -> FALSE Sun Dec 20 15:44:46 2009 : Info: Found Auth-Type = MSCHAP Sun Dec 20 15:44:46 2009 : Info: +- entering group MS-CHAP {...} Sun Dec 20 15:44:46 2009 : Info: [mschap] Told to do MS-CHAPv2 for Stephan.Kirsten with NT-Password Sun Dec 20 15:44:46 2009 : Info: [mschap] adding MS-CHAPv2 MPPE keys Sun Dec 20 15:44:46 2009 : Info: ++[mschap] returns ok Sun Dec 20 15:44:46 2009 : Info: +- entering group post-auth {...} Sun Dec 20 15:44:46 2009 : Info: [sql] expand: %{User-Name} -> Stephan.Kirsten Sun Dec 20 15:44:46 2009 : Info: [sql] sql_set_user escaped user --> 'Stephan.Kirsten' Sun Dec 20 15:44:46 2009 : Info: [sql] expand: %{User-Password} -> Sun Dec 20 15:44:46 2009 : Info: [sql] expand: %{Chap-Password} -> Sun Dec 20 15:44:46 2009 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'Stephan.Kirsten', '', 'Access-Accept', '2009-12-20 15:44:46') Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'Stephan.Kirsten', '', 'Access-Accept', '2009-12-20 15:44:46') Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql): Reserving sql socket id: 2 Sun Dec 20 15:44:46 2009 : Debug: rlm_sql (sql): Released sql socket id: 2 Sun Dec 20 15:44:46 2009 : Info: ++[sql] returns ok Sun Dec 20 15:44:46 2009 : Info: } # server pptp Sending Access-Accept of id 34 to 192.168.254.20 port 43443 Reply-Message = "USER Stephan.Kirsten: hat Traffic-Limit erreicht!" Mikrotik-Rate-Limit = "128k/128k" Mikrotik-Advertise-URL = "http://www.fbn-dd.de" WISPr-Redirection-URL = "10.64.1.240" Mikrotik-Advertise-Interval = 10 WISPr-Logoff-URL = "10.64.1.240" MS-CHAP2-Success = 0x01533d44454546344137334242323735443732373841354545333337383841324543464439434537323836 MS-MPPE-Recv-Key = 0xfbcf5a773c0fda641859474e0e3cb0b8 MS-MPPE-Send-Key = 0xa96a099e1d07b693843bd4f1f447068c MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 Sun Dec 20 15:44:46 2009 : Info: Finished request 0.
I have a question regarding this debug log output. I'm a bit confused about this logic operations and the boolean result:
Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-4} -> 32933844 Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856 Sun Dec 20 15:44:46 2009 : Info: ? Evaluating ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") -> TRUE Hmm have you tried using direct references to the attributes? i.e. if(control:Tmp-Integer-4 >= control:Tmp-Integer-5). The values of the attributes will likely be converted to a strings before comparison, might be causing the odd result...
-Arran
Arran Cudbard-Bell schrieb:
I have a question regarding this debug log output. I'm a bit confused about this logic operations and the boolean result:
Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-4} -> 32933844 Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856 Sun Dec 20 15:44:46 2009 : Info: ? Evaluating ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") -> TRUE
Hmm have you tried using direct references to the attributes? i.e. if(control:Tmp-Integer-4 >= control:Tmp-Integer-5). The values of the attributes will likely be converted to a strings before comparison, might be causing the odd result...
I tried your suggestion, but then the parsing breaks Sun Dec 20 17:20:33 2009 : Info: ++? if (control:Tmp-Integer-4 >= control:Tmp-Integer-5) Sun Dec 20 17:20:33 2009 : Info: Failed parsing "control:Tmp-Integer-5": Unknown value control:Tmp-Integer-5 for attribute Tmp-Integer-4 Sun Dec 20 17:20:33 2009 : Info: ++? if (control:Tmp-Integer-4 < control:Tmp-Integer-5) Sun Dec 20 17:20:33 2009 : Info: Failed parsing "control:Tmp-Integer-5": Unknown value control:Tmp-Integer-5 for attribute Tmp-Integer-4 -Stephan
On 20/12/2009 17:40, Stephan Kirsten wrote:
Arran Cudbard-Bell schrieb:
I have a question regarding this debug log output. I'm a bit confused about this logic operations and the boolean result:
Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-4} -> 32933844 Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856 Sun Dec 20 15:44:46 2009 : Info: ? Evaluating ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") -> TRUE
Hmm have you tried using direct references to the attributes? i.e. if(control:Tmp-Integer-4 >= control:Tmp-Integer-5). The values of the attributes will likely be converted to a strings before comparison, might be causing the odd result...
I tried your suggestion, but then the parsing breaks
Sun Dec 20 17:20:33 2009 : Info: ++? if (control:Tmp-Integer-4 >= control:Tmp-Integer-5) Sun Dec 20 17:20:33 2009 : Info: Failed parsing "control:Tmp-Integer-5": Unknown value control:Tmp-Integer-5 for attribute Tmp-Integer-4 Sun Dec 20 17:20:33 2009 : Info: ++? if (control:Tmp-Integer-4 < control:Tmp-Integer-5) Sun Dec 20 17:20:33 2009 : Info: Failed parsing "control:Tmp-Integer-5": Unknown value control:Tmp-Integer-5 for attribute Tmp-Integer-4
Hmm maybe the right operand has to be an integer or string value. Try a mix? if (control:Tmp-Integer-4 < "%{control:Tmp-Integer-5}") The logic being that the left operand is known to be an integer... -Arran
Arran Cudbard-Bell <a.cudbard-bell@sussex.ac.uk> wrote:
I have a question regarding this debug log output. I'm a bit confused about this logic operations and the boolean result:
Sun Dec 20 15:44:46 2009 : Info: ++? if ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-4} -> 32933844 Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856 Sun Dec 20 15:44:46 2009 : Info: ? Evaluating ("%{control:Tmp-Integer-4}" >= "%{control:Tmp-Integer-5}") -> TRUE
Hmm have you tried using direct references to the attributes? i.e. if(control:Tmp-Integer-4 >= control:Tmp-Integer-5). The values of the attributes will likely be converted to a strings before comparison, might be causing the odd result...
I probably would personally be more inclinded to reduce accuracy and trim the last three octets of the string to effectively give you kilobyte accuracy which probably is close enough for your needs. Hopefully not many shift 2TB in the time period you are handling :) This will probably do you well until Alan gives you 64bit counters; obviously wait out for the 64bit counters if you can though. Cheers -- Alexander Clouter .sigmonster says: To avoid suffocation, keep away from children.
Stephan Kirsten wrote:
I have a question regarding this debug log output. I'm a bit confused about this logic operations and the boolean result:
"signed 32-bit integer"
Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856
That's larger than 2^31. :(
So how does this come together? The debug log is attached to this mail.
I hope someone ca clarify this problem
I'll take a look at making these checks signed 64-bit, or unsigned 32-bit for 2.1.8. Alan DeKok.
On 20/12/2009 17:46, Alan DeKok wrote:
Stephan Kirsten wrote:
I have a question regarding this debug log output. I'm a bit confused about this logic operations and the boolean result:
"signed 32-bit integer"
Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856
That's larger than 2^31. :(
Ahh ok. Sorry seeing buggy code where there isn't any :)
Alan DeKok schrieb:
Stephan Kirsten wrote:
I have a question regarding this debug log output. I'm a bit confused about this logic operations and the boolean result:
"signed 32-bit integer"
okay, thanx for pointing me on this. i've read in the dictionary.freeradius.intern file that these attribute are integer, but i wasnt sure about the size and obviously it can handle 64bit values. the only limitiation i've found was in rlm_expr, where it says, it can handle unsigned 32-bit integers where can i read more about this limitation?
Sun Dec 20 15:44:46 2009 : Info: expand: %{control:Tmp-Integer-5} -> 2785017856
That's larger than 2^31. :(
obviously :/
So how does this come together? The debug log is attached to this mail.
I hope someone ca clarify this problem
I'll take a look at making these checks signed 64-bit, or unsigned 32-bit for 2.1.8.
that would be great, also enhancing expr for signed 64-bit integer would be appreciated :) And it's of course good to know, that freeradius is working as designed :) -Stephan
Stephan Kirsten wrote:
i've read in the dictionary.freeradius.intern file that these attribute are integer, but i wasnt sure about the size and obviously it can handle 64bit values.
Integers in RADIUS are unsigned 32-bit integers.
the only limitiation i've found was in rlm_expr, where it says, it can handle unsigned 32-bit integers
where can i read more about this limitation?
The RFC's, such as they are. Alan DeKok.
participants (4)
-
Alan DeKok -
Alexander Clouter -
Arran Cudbard-Bell -
Stephan Kirsten