evaluated result is wrong

20 Dec 2009

      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.

evaluated result is wrong

Stephan Kirsten