DHCP with Oracle and sqlippool
Hello everyone I am trying to set up FreeRADIUS as a DHCP server for use with an IP pool in an Oracle DB. I built the latest version from git, and added some basic config to test the DHCP pool functionality. However, the server does not process any requests and gives the following error: Received DHCP-Discover of id cf875833 from 10.180.1.1:67 to 10.160.0.254:67 Threads: total/active/spare threads = 0/0/0 Something is blocking the server. There are 0 packets in the queue, waiting to be processed. Ignoring the new request. (0) Cleaning up request packet ID 3481753651 with timestamp +302 I would be very grateful if someone could advise what the problem is. The full debug log is as follows: radiusd: FreeRADIUS Version 3.1.0 (git #10ffd5b), for host x86_64-unknown-linux-gnu, built on Feb 21 2014 at 13:50:22 Copyright (C) 1999-2014 The FreeRADIUS server project and contributors There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE You may redistribute copies of FreeRADIUS under the terms of the GNU General Public License For more information about these matters, see the file named COPYRIGHT Starting - reading configuration files ... including dictionary file /usr/local/share/freeradius/dictionary including dictionary file /usr/local/etc/raddb/dictionary including configuration file /usr/local/etc/raddb/radiusd.conf including configuration file /usr/local/etc/raddb/clients.conf including files in directory /usr/local/etc/raddb/mods-enabled/ including configuration file /usr/local/etc/raddb/mods-enabled/expr including configuration file /usr/local/etc/raddb/mods-enabled/ntlm_auth including configuration file /usr/local/etc/raddb/mods-enabled/logintime including configuration file /usr/local/etc/raddb/mods-enabled/expiration including configuration file /usr/local/etc/raddb/mods-enabled/realm including configuration file /usr/local/etc/raddb/mods-enabled/detail.log including configuration file /usr/local/etc/raddb/mods-enabled/pap including configuration file /usr/local/etc/raddb/mods-enabled/digest including configuration file /usr/local/etc/raddb/mods-enabled/attr_filter including configuration file /usr/local/etc/raddb/mods-enabled/chap including configuration file /usr/local/etc/raddb/mods-enabled/eap including configuration file /usr/local/etc/raddb/mods-enabled/utf8 including configuration file /usr/local/etc/raddb/mods-enabled/replicate including configuration file /usr/local/etc/raddb/mods-enabled/detail including configuration file /usr/local/etc/raddb/mods-enabled/always including configuration file /usr/local/etc/raddb/mods-enabled/echo including configuration file /usr/local/etc/raddb/mods-enabled/cache_eap including configuration file /usr/local/etc/raddb/mods-enabled/linelog including configuration file /usr/local/etc/raddb/mods-enabled/files including configuration file /usr/local/etc/raddb/mods-enabled/dhcp including configuration file /usr/local/etc/raddb/mods-enabled/dynamic_clients including configuration file /usr/local/etc/raddb/mods-enabled/mschap including configuration file /usr/local/etc/raddb/mods-enabled/radutmp including configuration file /usr/local/etc/raddb/mods-enabled/unix including configuration file /usr/local/etc/raddb/mods-enabled/sql including configuration file /usr/local/etc/raddb/mods-config/sql/main/oracle/queries.conf including configuration file /usr/local/etc/raddb/mods-enabled/passwd including configuration file /usr/local/etc/raddb/mods-enabled/sradutmp including configuration file /usr/local/etc/raddb/mods-enabled/exec including configuration file /usr/local/etc/raddb/mods-enabled/soh including configuration file /usr/local/etc/raddb/mods-enabled/dhcp_sqlippool including configuration file /usr/local/etc/raddb/mods-config/sql/ippool-dhcp/oracle/queries.conf including configuration file /usr/local/etc/raddb/mods-enabled/preprocess including configuration file /usr/local/etc/raddb/mods-enabled/sqlippool including configuration file /usr/local/etc/raddb/mods-config/sql/ippool/mysql/queries.conf including files in directory /usr/local/etc/raddb/policy.d/ including configuration file /usr/local/etc/raddb/policy.d/canonicalization including configuration file /usr/local/etc/raddb/policy.d/control including configuration file /usr/local/etc/raddb/policy.d/filter including configuration file /usr/local/etc/raddb/policy.d/eap including configuration file /usr/local/etc/raddb/policy.d/dhcp including configuration file /usr/local/etc/raddb/policy.d/operator-name including configuration file /usr/local/etc/raddb/policy.d/cui including configuration file /usr/local/etc/raddb/policy.d/accounting including files in directory /usr/local/etc/raddb/sites-enabled/ including configuration file /usr/local/etc/raddb/sites-enabled/dhcp_pool main { security { allow_core_dumps = no } } main { name = "radiusd" prefix = "/usr/local" localstatedir = "/usr/local/var" sbindir = "/usr/local/sbin" logdir = "/usr/local/var/log/radius" run_dir = "/usr/local/var/run/radiusd" libdir = "/usr/local/lib" radacctdir = "/usr/local/var/log/radius/radacct" hostname_lookups = no max_request_time = 30 cleanup_delay = 5 max_requests = 1024 pidfile = "/usr/local/var/run/radiusd/radiusd.pid" checkrad = "/usr/local/sbin/checkrad" debug_level = 0 proxy_requests = no log { stripped_names = no auth = no auth_badpass = no auth_goodpass = no colourise = yes } security { max_attributes = 200 reject_delay = 1 status_server = yes } } radiusd: #### Loading Realms and Home Servers #### radiusd: #### Loading Clients #### client localhost { ipaddr = 127.0.0.1 require_message_authenticator = no secret = <<< secret >>> nas_type = "other" proto = "*" limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } radiusd: #### Instantiating modules #### instantiate { } modules { # Loaded module rlm_expr # Instantiating module "expr" from file /usr/local/etc/raddb/mods-enabled/expr expr { safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" } # Loaded module rlm_exec # Instantiating module "ntlm_auth" from file /usr/local/etc/raddb/mods-enabled/ntlm_auth exec ntlm_auth { wait = yes program = "/path/to/ntlm_auth --request-nt-key --domain=MYDOMAIN --username=%{mschap:User-Name} --password=%{User-Password}" shell_escape = yes } # Loaded module rlm_logintime # Instantiating module "logintime" from file /usr/local/etc/raddb/mods-enabled/logintime logintime { minimum_timeout = 60 } # Loaded module rlm_expiration # Instantiating module "expiration" from file /usr/local/etc/raddb/mods-enabled/expiration # Loaded module rlm_realm # Instantiating module "IPASS" from file /usr/local/etc/raddb/mods-enabled/realm realm IPASS { format = "prefix" delimiter = "/" ignore_default = no ignore_null = no } # Instantiating module "suffix" from file /usr/local/etc/raddb/mods-enabled/realm realm suffix { format = "suffix" delimiter = "@" ignore_default = no ignore_null = no } # Instantiating module "realmpercent" from file /usr/local/etc/raddb/mods-enabled/realm realm realmpercent { format = "suffix" delimiter = "%" ignore_default = no ignore_null = no } # Instantiating module "ntdomain" from file /usr/local/etc/raddb/mods-enabled/realm realm ntdomain { format = "prefix" delimiter = "\" ignore_default = no ignore_null = no } # Loaded module rlm_detail # Instantiating module "auth_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail auth_log { filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d" header = "%t" permissions = 384 dir_permissions = 493 locking = no log_packet_header = no } rlm_detail (auth_log): 'User-Password' suppressed, will not appear in detail output # Instantiating module "reply_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail reply_log { filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/reply-detail-%Y%m%d" header = "%t" permissions = 384 dir_permissions = 493 locking = no log_packet_header = no } # Instantiating module "pre_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail pre_proxy_log { filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/pre-proxy-detail-%Y%m%d" header = "%t" permissions = 384 dir_permissions = 493 locking = no log_packet_header = no } # Instantiating module "post_proxy_log" from file /usr/local/etc/raddb/mods-enabled/detail.log detail post_proxy_log { filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d" header = "%t" permissions = 384 dir_permissions = 493 locking = no log_packet_header = no } # Loaded module rlm_pap # Instantiating module "pap" from file /usr/local/etc/raddb/mods-enabled/pap pap { auto_header = no normalise = yes } # Loaded module rlm_digest # Instantiating module "digest" from file /usr/local/etc/raddb/mods-enabled/digest # Loaded module rlm_attr_filter # Instantiating module "attr_filter.post-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter attr_filter attr_filter.post-proxy { filename = "/usr/local/etc/raddb/mods-config/attr_filter/post-proxy" key = "%{Realm}" relaxed = no } reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/post-proxy # Instantiating module "attr_filter.pre-proxy" from file /usr/local/etc/raddb/mods-enabled/attr_filter attr_filter attr_filter.pre-proxy { filename = "/usr/local/etc/raddb/mods-config/attr_filter/pre-proxy" key = "%{Realm}" relaxed = no } reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/pre-proxy # Instantiating module "attr_filter.access_reject" from file /usr/local/etc/raddb/mods-enabled/attr_filter attr_filter attr_filter.access_reject { filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_reject" key = "%{User-Name}" relaxed = no } reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_reject # Instantiating module "attr_filter.access_challenge" from file /usr/local/etc/raddb/mods-enabled/attr_filter attr_filter attr_filter.access_challenge { filename = "/usr/local/etc/raddb/mods-config/attr_filter/access_challenge" key = "%{User-Name}" relaxed = no } reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/access_challenge # Instantiating module "attr_filter.accounting_response" from file /usr/local/etc/raddb/mods-enabled/attr_filter attr_filter attr_filter.accounting_response { filename = "/usr/local/etc/raddb/mods-config/attr_filter/accounting_response" key = "%{User-Name}" relaxed = no } reading pairlist file /usr/local/etc/raddb/mods-config/attr_filter/accounting_response # Loaded module rlm_chap # Instantiating module "chap" from file /usr/local/etc/raddb/mods-enabled/chap # Loaded module rlm_eap # Instantiating module "eap" from file /usr/local/etc/raddb/mods-enabled/eap eap { default_eap_type = "md5" timer_expire = 60 ignore_unknown_eap_types = no mod_accounting_username_bug = no max_sessions = 4096 } # Linked to sub-module rlm_eap_md5 # Linked to sub-module rlm_eap_leap # Linked to sub-module rlm_eap_gtc gtc { challenge = "Password: " auth_type = "PAP" } # Linked to sub-module rlm_eap_tls tls { tls = "tls-common" } tls-config tls-common { rsa_key_exchange = no dh_key_exchange = yes rsa_key_length = 512 dh_key_length = 512 verify_depth = 0 ca_path = "/usr/local/etc/raddb/certs" pem_file_type = yes private_key_file = "/usr/local/etc/raddb/certs/server.pem" certificate_file = "/usr/local/etc/raddb/certs/server.pem" ca_file = "/usr/local/etc/raddb/certs/ca.pem" private_key_password = <<< secret >>> dh_file = "/usr/local/etc/raddb/certs/dh" fragment_size = 1024 include_length = yes check_crl = no cipher_list = "DEFAULT" ecdh_curve = "prime256v1" cache { enable = yes lifetime = 24 max_entries = 255 } verify { } ocsp { enable = no override_cert_url = yes url = "http://127.0.0.1/ocsp/" use_nonce = yes timeout = 0 softfail = yes } } # Linked to sub-module rlm_eap_ttls ttls { tls = "tls-common" default_eap_type = "md5" copy_request_to_tunnel = no use_tunneled_reply = no virtual_server = "inner-tunnel" include_length = yes require_client_cert = no } Using cached TLS configuration from previous invocation # Linked to sub-module rlm_eap_peap peap { tls = "tls-common" default_method = "mschapv2" copy_request_to_tunnel = no use_tunneled_reply = no proxy_tunneled_request_as_eap = yes virtual_server = "inner-tunnel" soh = no require_client_cert = no } Using cached TLS configuration from previous invocation # Linked to sub-module rlm_eap_mschapv2 mschapv2 { with_ntdomain_hack = no send_error = no } # Loaded module rlm_utf8 # Instantiating module "utf8" from file /usr/local/etc/raddb/mods-enabled/utf8 # Loaded module rlm_replicate # Instantiating module "replicate" from file /usr/local/etc/raddb/mods-enabled/replicate # Instantiating module "detail" from file /usr/local/etc/raddb/mods-enabled/detail detail { filename = "/usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d" header = "%t" permissions = 384 dir_permissions = 493 locking = no log_packet_header = no } # Loaded module rlm_always # Instantiating module "reject" from file /usr/local/etc/raddb/mods-enabled/always always reject { rcode = "reject" simulcount = 0 mpp = no } # Instantiating module "fail" from file /usr/local/etc/raddb/mods-enabled/always always fail { rcode = "fail" simulcount = 0 mpp = no } # Instantiating module "ok" from file /usr/local/etc/raddb/mods-enabled/always always ok { rcode = "ok" simulcount = 0 mpp = no } # Instantiating module "handled" from file /usr/local/etc/raddb/mods-enabled/always always handled { rcode = "handled" simulcount = 0 mpp = no } # Instantiating module "invalid" from file /usr/local/etc/raddb/mods-enabled/always always invalid { rcode = "invalid" simulcount = 0 mpp = no } # Instantiating module "userlock" from file /usr/local/etc/raddb/mods-enabled/always always userlock { rcode = "userlock" simulcount = 0 mpp = no } # Instantiating module "notfound" from file /usr/local/etc/raddb/mods-enabled/always always notfound { rcode = "notfound" simulcount = 0 mpp = no } # Instantiating module "noop" from file /usr/local/etc/raddb/mods-enabled/always always noop { rcode = "noop" simulcount = 0 mpp = no } # Instantiating module "updated" from file /usr/local/etc/raddb/mods-enabled/always always updated { rcode = "updated" simulcount = 0 mpp = no } # Instantiating module "echo" from file /usr/local/etc/raddb/mods-enabled/echo exec echo { wait = yes program = "/bin/echo %{User-Name}" input_pairs = "request" output_pairs = "reply" shell_escape = yes } # Loaded module rlm_cache # Instantiating module "cache_eap" from file /usr/local/etc/raddb/mods-enabled/cache_eap cache cache_eap { key = "%{%{control:State}:-%{%{reply:State}:-%{State}}}" ttl = 15 max_entries = 16384 epoch = 0 add_stats = no } # Loaded module rlm_linelog # Instantiating module "linelog" from file /usr/local/etc/raddb/mods-enabled/linelog linelog { filename = "/usr/local/var/log/radius/linelog" permissions = 384 format = "This is a log message for %{User-Name}" reference = "%{%{Packet-Type}:-format}" } # Instantiating module "linelog-dhcp" from file /usr/local/etc/raddb/mods-enabled/linelog linelog linelog-dhcp { filename = "/usr/local/var/log/radius/linelog-dhcp.log" permissions = 384 format = "" reference = "%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}" } # Loaded module rlm_files # Instantiating module "files" from file /usr/local/etc/raddb/mods-enabled/files files { filename = "/usr/local/etc/raddb/mods-config/files/authorize" usersfile = "/usr/local/etc/raddb/mods-config/files/authorize" acctusersfile = "/usr/local/etc/raddb/mods-config/files/accounting" preproxy_usersfile = "/usr/local/etc/raddb/mods-config/files/pre-proxy" compat = "no" } reading pairlist file /usr/local/etc/raddb/mods-config/files/authorize reading pairlist file /usr/local/etc/raddb/mods-config/files/authorize reading pairlist file /usr/local/etc/raddb/mods-config/files/accounting reading pairlist file /usr/local/etc/raddb/mods-config/files/pre-proxy # Loaded module rlm_dhcp # Instantiating module "dhcp" from file /usr/local/etc/raddb/mods-enabled/dhcp # Loaded module rlm_dynamic_clients # Instantiating module "dynamic_clients" from file /usr/local/etc/raddb/mods-enabled/dynamic_clients # Loaded module rlm_mschap # Instantiating module "mschap" from file /usr/local/etc/raddb/mods-enabled/mschap mschap { use_mppe = yes require_encryption = no require_strong = no with_ntdomain_hack = yes passchange { } allow_retry = yes } # Loaded module rlm_radutmp # Instantiating module "radutmp" from file /usr/local/etc/raddb/mods-enabled/radutmp radutmp { filename = "/usr/local/var/log/radius/radutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 384 caller_id = yes } # Loaded module rlm_unix # Instantiating module "unix" from file /usr/local/etc/raddb/mods-enabled/unix unix { radwtmp = "/usr/local/var/log/radius/radwtmp" } # Loaded module rlm_sql # Instantiating module "sql" from file /usr/local/etc/raddb/mods-enabled/sql sql { driver = "rlm_sql_oracle" server = "localhost" port = "" login = "foo" password = <<< secret >>> radius_db = "(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=foo)(PORT=1521))(CONNECT_DATA=(SID=bar)))" read_groups = yes read_clients = no delete_stale_sessions = yes sql_user_name = "%{User-Name}" default_user_profile = "" client_query = "SELECT id, nasname, shortname, type, secret, server FROM nas" authorize_check_query = "SELECT id,UserName,Attribute,Value,op FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER BY id" authorize_reply_query = "SELECT id,UserName,Attribute,Value,op FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER BY id" authorize_group_check_query = "SELECT radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op FROM radgroupcheck,radusergroup WHERE radusergroup.Username = '%{SQL-User-Name}' AND radusergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id" authorize_group_reply_query = "SELECT radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op FROM radgroupreply,radusergroup WHERE radusergroup.Username = '%{SQL-User-Name}' AND radusergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id" group_membership_query = "SELECT GroupName FROM radusergroup WHERE UserName='%{SQL-User-Name}'" simul_count_query = "" simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime IS NULL" safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /" } accounting { reference = "%{tolower:type.%{Acct-Status-Type}.query}" } post-auth { reference = ".query" } rlm_sql (sql): Driver rlm_sql_oracle (module rlm_sql_oracle) loaded and linked rlm_sql (sql): Attempting to connect to database "(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=foo)(PORT1521))(CONNECT_DATA=(SID=bar)))" rlm_sql (sql): Initialising connection pool pool { start = 5 min = 4 max = 32 spare = 3 uses = 0 lifetime = 0 cleanup_delay = 5 idle_timeout = 60 spread = no } rlm_sql (sql): Opening additional connection (0) rlm_sql (sql): Opening additional connection (1) rlm_sql (sql): Opening additional connection (2) rlm_sql (sql): Opening additional connection (3) rlm_sql (sql): Opening additional connection (4) # Loaded module rlm_passwd # Instantiating module "etc_passwd" from file /usr/local/etc/raddb/mods-enabled/passwd passwd etc_passwd { filename = "/etc/passwd" format = "*User-Name:Crypt-Password:" delimiter = ":" ignore_nislike = no ignore_empty = yes allow_multiple_keys = no hash_size = 100 } rlm_passwd: nfields: 3 keyfield 0(User-Name) listable: no # Instantiating module "sradutmp" from file /usr/local/etc/raddb/mods-enabled/sradutmp radutmp sradutmp { filename = "/usr/local/var/log/radius/sradutmp" username = "%{User-Name}" case_sensitive = yes check_with_nas = yes permissions = 420 caller_id = no } # Instantiating module "exec" from file /usr/local/etc/raddb/mods-enabled/exec exec { wait = no input_pairs = "request" shell_escape = yes timeout = 10 } # Loaded module rlm_soh # Instantiating module "soh" from file /usr/local/etc/raddb/mods-enabled/soh soh { dhcp = yes } # Loaded module rlm_sqlippool # Instantiating module "dhcp_sqlippool" from file /usr/local/etc/raddb/mods-enabled/dhcp_sqlippool sqlippool dhcp_sqlippool { sql_module_instance = "sql" lease_duration = 7200 pool_name = "" default_pool = "main_pool" allocate_begin = "COMMIT" allocate_clear = " UPDATE radippool SET EXPIRY_TIME = CURRENT_TIMESTAMP - INTERVAL '1' SECOND(1) WHERE POOL_KEY = '%{Calling-Station-Id}'" allocate_find = " WITH POOLS AS ( SELECT * FROM radippool WHERE EXPIRY_TIME < CURRENT_TIMESTAMP AND POOL_NAME = '%{control:Pool-Name}') SELECT FRAMEDIPADDRESS FROM ( SELECT FRAMEDIPADDRESS FROM POOLS WHERE POOL_KEY = '%{Calling-Station-Id}' OR (NOT EXISTS ( SELECT 1 FROM POOLS WHERE POOL_KEY = '%{Calling-Station-Id}'))) WHERE ROWNUM = 1 FOR UPDATE" allocate_update = " UPDATE radippool SET NASIPADDRESS = '%{NAS-IP-Address}', POOL_KEY = '%{Calling-Station-Id}', CALLINGSTATIONID = '%{Mac-Addr}', USERNAME = '%{SQL-User-Name}', EXPIRY_TIME = CURRENT_TIMESTAMP + INTERVAL '7200' SECOND(1) WHERE FRAMEDIPADDRESS = '%I'" allocate_commit = "COMMIT" pool_check = "" start_begin = "COMMIT" start_update = " UPDATE radippool SET EXPIRY_TIME = CURRENT_TIMESTAMP + INTERVAL '7200' SECOND(1) WHERE NASIPADDRESS = '%{NAS-IP-Address}' AND POOL_NAME = '%{control:Pool-Name}' AND POOL_KEY = '%{Calling-Station-Id}' AND FRAMEDIPADDRESS = '%{Framed-IP-Address}'" start_commit = "COMMIT" alive_begin = "COMMIT" alive_update = " UPDATE radippool SET EXPIRY_TIME = CURRENT_TIMESTAMP + INTERVAL '7200' SECOND(1) WHERE POOL_KEY = '%{Calling-Station-Id}' AND POOL_NAME = '%{control:Pool-Name}' AND FRAMEDIPADDRESS = '%{Framed-IP-Address}'" alive_commit = "COMMIT" stop_begin = "COMMIT" stop_clear = " UPDATE radippool SET EXPIRY_TIME = CURRENT_TIMESTAMP - INTERVAL '1' SECOND(1) WHERE POOL_KEY = '%{Calling-Station-Id}'" stop_commit = "COMMIT" on_begin = "COMMIT" on_clear = " UPDATE radippool SET EXPIRY_TIME = CURRENT_TIMESTAMP - INTERVAL '1' SECOND(1) WHERE NASIPADDRESS = '%{Nas-IP-Address}'" on_commit = "COMMIT" off_begin = "COMMIT" off_clear = " UPDATE radippool SET EXPIRY_TIME = CURRENT_TIMESTAMP - INTERVAL '1' SECOND(1) WHERE NASIPADDRESS = '%{Nas-IP-Address}'" off_commit = "COMMIT" messages { } } # Loaded module rlm_preprocess # Instantiating module "preprocess" from file /usr/local/etc/raddb/mods-enabled/preprocess preprocess { huntgroups = "/usr/local/etc/raddb/mods-config/preprocess/huntgroups" hints = "/usr/local/etc/raddb/mods-config/preprocess/hints" with_ascend_hack = no ascend_channels_per_line = 23 with_ntdomain_hack = no with_specialix_jetstream_hack = no with_cisco_vsa_hack = no with_alvarion_vsa_hack = no } reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/huntgroups reading pairlist file /usr/local/etc/raddb/mods-config/preprocess/hints # Instantiating module "sqlippool" from file /usr/local/etc/raddb/mods-enabled/sqlippool sqlippool { sql_module_instance = "sql" lease_duration = 3600 pool_name = "" default_pool = "main_pool" allocate_begin = "START TRANSACTION" allocate_clear = "UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE expiry_time <= NOW() - INTERVAL 1 SECOND AND nasipaddress = '%{Nas-IP-Address}'" allocate_find = "SELECT framedipaddress FROM radippool WHERE pool_name = '%{control:Pool-Name}' AND (expiry_time < NOW() OR expiry_time IS NULL) ORDER BY (username <> '%{User-Name}'), (callingstationid <> '%{Calling-Station-Id}'), expiry_time LIMIT 1 FOR UPDATE" allocate_update = "UPDATE radippool SET nasipaddress = '%{NAS-IP-Address}', pool_key = '%{NAS-Port}', callingstationid = '%{Calling-Station-Id}', username = '%{User-Name}', expiry_time = NOW() + INTERVAL 3600 SECOND WHERE framedipaddress = '%I' AND expiry_time IS NULL" allocate_commit = "COMMIT" pool_check = "SELECT id FROM radippool WHERE pool_name='%{control:Pool-Name}' LIMIT 1" start_begin = "START TRANSACTION" start_update = "UPDATE radippool SET expiry_time = NOW() + INTERVAL 3600 SECOND WHERE nasipaddress = '%{NAS-IP-Address}' AND pool_key = '%{NAS-Port}' AND username = '%{User-Name}' AND callingstationid = '%{Calling-Station-Id}' AND framedipaddress = '%{Framed-IP-Address}'" start_commit = "COMMIT" alive_begin = "START TRANSACTION" alive_update = "UPDATE radippool SET expiry_time = NOW() + INTERVAL 3600 SECOND WHERE nasipaddress = '%{Nas-IP-Address}' AND pool_key = '%{NAS-Port}' AND username = '%{User-Name}' AND callingstationid = '%{Calling-Station-Id}' AND framedipaddress = '%{Framed-IP-Address}'" alive_commit = "COMMIT" stop_begin = "START TRANSACTION" stop_clear = "UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE nasipaddress = '%{Nas-IP-Address}' AND pool_key = '%{NAS-Port}' AND username = '%{User-Name}' AND callingstationid = '%{Calling-Station-Id}' AND framedipaddress = '%{Framed-IP-Address}'" stop_commit = "COMMIT" on_begin = "START TRANSACTION" on_clear = "UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE nasipaddress = '%{Nas-IP-Address}'" on_commit = "COMMIT" off_begin = "START TRANSACTION" off_clear = "UPDATE radippool SET nasipaddress = '', pool_key = 0, callingstationid = '', username = '', expiry_time = NULL WHERE nasipaddress = '%{Nas-IP-Address}'" off_commit = "COMMIT" messages { exists = "Existing IP: %{reply:Framed-IP-Address} (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name})" success = "Allocated IP: %{reply:Framed-IP-Address} from %{control:Pool-Name} (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name})" clear = "Released IP %{Framed-IP-Address} (did %{Called-Station-Id} cli %{Calling-Station-Id} user %{User-Name})" failed = "IP Allocation FAILED from %{control:Pool-Name} (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name})" nopool = "No Pool-Name defined (did %{Called-Station-Id} cli %{Calling-Station-Id} port %{NAS-Port} user %{User-Name})" } } } # modules radiusd: #### Loading Virtual Servers #### server { # from file /usr/local/etc/raddb/radiusd.conf } # server server dhcp { # from file /usr/local/etc/raddb/sites-enabled/dhcp_pool # Loading dictionary.dhcp # Loading dhcp DHCP-Discover {...} # Loading dhcp DHCP-Request {...} # Loading dhcp DHCP-Release {...} # Loading dhcp DHCP-Inform {...} # Loading dhcp DHCP-Decline {...} # Loading dhcp {...} } # server dhcp radiusd: #### Opening IP addresses and Ports #### listen { type = "dhcp" ipaddr = 0.0.0.0 port = 67 } Listening on dhcp interface eth1 address * port 67 as server dhcp Ready to process requests Received DHCP-Discover of id cf875833 from 10.180.1.1:67 to 10.160.0.254:67 Threads: total/active/spare threads = 0/0/0 Something is blocking the server. There are 0 packets in the queue, waiting to be processed. Ignoring the new request. (0) Cleaning up request packet ID 3481753651 with timestamp +302
Thanks for the info. It is looking better with 3.0.1. I will share my oracle configs once I have proved that they work. On 21 February 2014 16:41, Alan DeKok <aland@deployingradius.com> wrote:
Бен Томпсон wrote:
radiusd: FreeRADIUS Version 3.1.0 (git #10ffd5b), for host
Don't use the "master" branch. Use an official release.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
olks, I have hit a problem and would would be grateful if you could have a quick look at it for me. I am trying to use the Option 82 data from a DHCP request, but for some reason the Circuit ID is changing during the procession for the request. Here is the reqest coming in and then getting processed by the linelog module: Received DHCP-Request of id 721fc604 from 10.180.1.1:67 to 10.160.0.254:67 0: 01 01 06 01 72 1f c6 04 00 a5 00 00 0a b4 01 05 16: 00 00 00 00 00 00 00 00 0a b4 01 01 50 af 73 18 32: ed 98 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 03 0c 07 73 75 70 70 6f 72 74 37 0d 01 1c 256: 02 03 0f 06 77 0c 2c 2f 1a 79 2a 52 12 01 08 00 272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 1 DHCP-Transaction-Id = 1914684932 DHCP-Number-of-Seconds = 165 DHCP-Flags = 0 DHCP-Client-IP-Address = 10.180.1.5 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 10.180.1.1 DHCP-Client-Hardware-Address = 50:af:73:18:ed:98 DHCP-Message-Type += DHCP-Request DHCP-Hostname += 'support' DHCP-Parameter-Request-List += DHCP-Subnet-Mask DHCP-Parameter-Request-List += DHCP-Broadcast-Address DHCP-Parameter-Request-List += DHCP-Time-Offset DHCP-Parameter-Request-List += DHCP-Router-Address DHCP-Parameter-Request-List += DHCP-Domain-Name DHCP-Parameter-Request-List += DHCP-Domain-Name-Server DHCP-Parameter-Request-List += DHCP-Domain-Search DHCP-Parameter-Request-List += DHCP-Hostname DHCP-Parameter-Request-List += DHCP-NETBIOS-Name-Servers DHCP-Parameter-Request-List += DHCP-NETBIOS DHCP-Parameter-Request-List += DHCP-Interface-MTU-Size DHCP-Parameter-Request-List += DHCP-Classless-Static-Route DHCP-Parameter-Request-List += DHCP-NTP-Servers DHCP-Relay-Circuit-Id = 0x000604b101000001 Mon Feb 24 16:51:36 2014 : Debug: Trying sub-section dhcp DHCP-Request {...} Mon Feb 24 16:51:36 2014 : Debug: (0) dhcp DHCP-Request { Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: calling linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: %{%{reply:DHCP-Message-Type}:- %{request:DHCP-Message-Type}} Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: if { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 2 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: else { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}" -> 'DHCP-Request' Mon Feb 24 16:51:36 2014 : Debug: /usr/local/var/log/radius/linelog-dhcp.log Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal: '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "/usr/local/var/log/radius/linelog-dhcp.log" -> '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: %S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ... Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal (with %): 'S' Mon Feb 24 16:51:36 2014 : Debug: literal: ' --> Transaction-ID: ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Transaction-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' REQUEST: [' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Client-Hardware-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '] via (' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Gateway-IP-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '), hop count = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Hop-Count Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ', Relay = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Remote-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' / ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Circuit-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' ...' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ..." -> '2014-02-24 16:51:36 --> Transaction-ID: 1914684932 REQUEST: [50:af:73:18:ed:98] via (10.180.1.1), hop count = 1, Relay = 0x00030f1ae32c / 0x5d20766961202800 ...' Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: returned from linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: (0) [linelog-dhcp] = ok As you can see, the attribute DHCP-Relay-Circuit-Id starts of with value "0x000604b101000001" but by the time it is processed by linelog it has value "0x5d20766961202800" Here is the full debug output: http://pastebin.com/b9RXPRD0 On 21 February 2014 19:02, Бен Томпсон <b.thompson@latera.ru> wrote:
Thanks for the info. It is looking better with 3.0.1. I will share my oracle configs once I have proved that they work.
On 21 February 2014 16:41, Alan DeKok <aland@deployingradius.com> wrote:
Бен Томпсон wrote:
radiusd: FreeRADIUS Version 3.1.0 (git #10ffd5b), for host
Don't use the "master" branch. Use an official release.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru
тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
Sorry, my previous email was not formatted correctly. Everyone, I have a problem and would would be grateful if you could have a quick look at it for me. I am trying to use the Option 82 data from a DHCP request, but for some reason the Circuit ID is changing during the processing of the request. Here is the reqest coming in and then getting processed by the linelog module: Received DHCP-Request of id 721fc604 from 10.180.1.1:67 to 10.160.0.254:67 0: 01 01 06 01 72 1f c6 04 00 a5 00 00 0a b4 01 05 16: 00 00 00 00 00 00 00 00 0a b4 01 01 50 af 73 18 32: ed 98 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 03 0c 07 73 75 70 70 6f 72 74 37 0d 01 1c 256: 02 03 0f 06 77 0c 2c 2f 1a 79 2a 52 12 01 08 00 272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 1 DHCP-Transaction-Id = 1914684932 DHCP-Number-of-Seconds = 165 DHCP-Flags = 0 DHCP-Client-IP-Address = 10.180.1.5 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 10.180.1.1 DHCP-Client-Hardware-Address = 50:af:73:18:ed:98 DHCP-Message-Type += DHCP-Request DHCP-Hostname += 'support' DHCP-Parameter-Request-List += DHCP-Subnet-Mask DHCP-Parameter-Request-List += DHCP-Broadcast-Address DHCP-Parameter-Request-List += DHCP-Time-Offset DHCP-Parameter-Request-List += DHCP-Router-Address DHCP-Parameter-Request-List += DHCP-Domain-Name DHCP-Parameter-Request-List += DHCP-Domain-Name-Server DHCP-Parameter-Request-List += DHCP-Domain-Search DHCP-Parameter-Request-List += DHCP-Hostname DHCP-Parameter-Request-List += DHCP-NETBIOS-Name-Servers DHCP-Parameter-Request-List += DHCP-NETBIOS DHCP-Parameter-Request-List += DHCP-Interface-MTU-Size DHCP-Parameter-Request-List += DHCP-Classless-Static-Route DHCP-Parameter-Request-List += DHCP-NTP-Servers DHCP-Relay-Circuit-Id = 0x000604b101000001 Mon Feb 24 16:51:36 2014 : Debug: Trying sub-section dhcp DHCP-Request {...} Mon Feb 24 16:51:36 2014 : Debug: (0) dhcp DHCP-Request { Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: calling linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: %{%{reply:DHCP-Message-Type}:- %{request:DHCP-Message-Type}} Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: if { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 2 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: else { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}" -> 'DHCP-Request' Mon Feb 24 16:51:36 2014 : Debug: /usr/local/var/log/radius/linelog-dhcp.log Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal: '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "/usr/local/var/log/radius/linelog-dhcp.log" -> '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: %S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ... Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal (with %): 'S' Mon Feb 24 16:51:36 2014 : Debug: literal: ' --> Transaction-ID: ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Transaction-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' REQUEST: [' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Client-Hardware-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '] via (' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Gateway-IP-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '), hop count = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Hop-Count Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ', Relay = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Remote-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' / ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Circuit-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' ...' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ..." -> '2014-02-24 16:51:36 --> Transaction-ID: 1914684932 REQUEST: [50:af:73:18:ed:98] via (10.180.1.1), hop count = 1, Relay = 0x00030f1ae32c / 0x5d20766961202800 ...' Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: returned from linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: (0) [linelog-dhcp] = ok As you can see, the attribute DHCP-Relay-Circuit-Id starts of with value "0x000604b101000001" but by the time it is processed by linelog it has value "0x5d20766961202800" Here is the full debug output: http://pastebin.com/b9RXPRD0 On 24 February 2014 21:28, Бен Томпсон <b.thompson@latera.ru> wrote:
olks, I have hit a problem and would would be grateful if you could have a quick look at it for me. I am trying to use the Option 82 data from a DHCP request, but for some reason the Circuit ID is changing during the procession for the request.
Here is the reqest coming in and then getting processed by the linelog module:
Received DHCP-Request of id 721fc604 from 10.180.1.1:67 to 10.160.0.254:67 0: 01 01 06 01 72 1f c6 04 00 a5 00 00 0a b4 01 05 16: 00 00 00 00 00 00 00 00 0a b4 01 01 50 af 73 18 32: ed 98 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 03 0c 07 73 75 70 70 6f 72 74 37 0d 01 1c 256: 02 03 0f 06 77 0c 2c 2f 1a 79 2a 52 12 01 08 00 272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 1 DHCP-Transaction-Id = 1914684932 DHCP-Number-of-Seconds = 165 DHCP-Flags = 0 DHCP-Client-IP-Address = 10.180.1.5 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 10.180.1.1 DHCP-Client-Hardware-Address = 50:af:73:18:ed:98 DHCP-Message-Type += DHCP-Request DHCP-Hostname += 'support' DHCP-Parameter-Request-List += DHCP-Subnet-Mask DHCP-Parameter-Request-List += DHCP-Broadcast-Address DHCP-Parameter-Request-List += DHCP-Time-Offset DHCP-Parameter-Request-List += DHCP-Router-Address DHCP-Parameter-Request-List += DHCP-Domain-Name DHCP-Parameter-Request-List += DHCP-Domain-Name-Server DHCP-Parameter-Request-List += DHCP-Domain-Search DHCP-Parameter-Request-List += DHCP-Hostname DHCP-Parameter-Request-List += DHCP-NETBIOS-Name-Servers DHCP-Parameter-Request-List += DHCP-NETBIOS DHCP-Parameter-Request-List += DHCP-Interface-MTU-Size DHCP-Parameter-Request-List += DHCP-Classless-Static-Route DHCP-Parameter-Request-List += DHCP-NTP-Servers DHCP-Relay-Circuit-Id = 0x000604b101000001 Mon Feb 24 16:51:36 2014 : Debug: Trying sub-section dhcp DHCP-Request {...} Mon Feb 24 16:51:36 2014 : Debug: (0) dhcp DHCP-Request { Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: calling linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: %{%{reply:DHCP-Message-Type}:- %{request:DHCP-Message-Type}} Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: if { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 2 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: else { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}" -> 'DHCP-Request' Mon Feb 24 16:51:36 2014 : Debug: /usr/local/var/log/radius/linelog-dhcp.log Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal: '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "/usr/local/var/log/radius/linelog-dhcp.log" -> '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: %S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ... Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal (with %): 'S' Mon Feb 24 16:51:36 2014 : Debug: literal: ' --> Transaction-ID: ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Transaction-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' REQUEST: [' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Client-Hardware-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '] via (' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Gateway-IP-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '), hop count = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Hop-Count Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ', Relay = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Remote-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' / ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Circuit-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' ...' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ..." -> '2014-02-24 16:51:36 --> Transaction-ID: 1914684932 REQUEST: [50:af:73:18:ed:98] via (10.180.1.1), hop count = 1, Relay = 0x00030f1ae32c / 0x5d20766961202800 ...' Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: returned from linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: (0) [linelog-dhcp] = ok
As you can see, the attribute DHCP-Relay-Circuit-Id starts of with value "0x000604b101000001" but by the time it is processed by linelog it has value "0x5d20766961202800"
Here is the full debug output: http://pastebin.com/b9RXPRD0
On 21 February 2014 19:02, Бен Томпсон <b.thompson@latera.ru> wrote:
Thanks for the info. It is looking better with 3.0.1. I will share my oracle configs once I have proved that they work.
On 21 February 2014 16:41, Alan DeKok <aland@deployingradius.com> wrote:
Бен Томпсон wrote:
radiusd: FreeRADIUS Version 3.1.0 (git #10ffd5b), for host
Don't use the "master" branch. Use an official release.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru
тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru
тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
Folks, I also noticed that the attribute DHCP-Relay-Remote-Id is not printed underneath the hex dumpbelow: Received DHCP-Request of id 721fc604 from 10.180.1.1:67 to 10.160.0.254:67 0: 01 01 06 01 72 1f c6 04 00 a5 00 00 0a b4 01 05 16: 00 00 00 00 00 00 00 00 0a b4 01 01 50 af 73 18 32: ed 98 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 03 0c 07 73 75 70 70 6f 72 74 37 0d 01 1c 256: 02 03 0f 06 77 0c 2c 2f 1a 79 2a 52 12 01 08 00 272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 1 DHCP-Transaction-Id = 1914684932 DHCP-Number-of-Seconds = 165 DHCP-Flags = 0 DHCP-Client-IP-Address = 10.180.1.5 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 10.180.1.1 DHCP-Client-Hardware-Address = 50:af:73:18:ed:98 DHCP-Message-Type += DHCP-Request DHCP-Hostname += 'support' DHCP-Parameter-Request-List += DHCP-Subnet-Mask DHCP-Parameter-Request-List += DHCP-Broadcast-Address DHCP-Parameter-Request-List += DHCP-Time-Offset DHCP-Parameter-Request-List += DHCP-Router-Address DHCP-Parameter-Request-List += DHCP-Domain-Name DHCP-Parameter-Request-List += DHCP-Domain-Name-Server DHCP-Parameter-Request-List += DHCP-Domain-Search DHCP-Parameter-Request-List += DHCP-Hostname DHCP-Parameter-Request-List += DHCP-NETBIOS-Name-Servers DHCP-Parameter-Request-List += DHCP-NETBIOS DHCP-Parameter-Request-List += DHCP-Interface-MTU-Size DHCP-Parameter-Request-List += DHCP-Classless-Static-Route DHCP-Parameter-Request-List += DHCP-NTP-Servers DHCP-Relay-Circuit-Id = 0x000604b101000001 Mon Feb 24 16:51:36 2014 : Debug: Trying sub-section dhcp DHCP-Request {...} It can be seen the the hex dump contains both Cicuit-Id (06 04 b1 01 00 00 01) and Remote-Id (00 03 0f 1a e3 2c): 272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff But these are not printed underneath. If I can help to debug this please let me know what to do. Thanks Ben On 25 February 2014 07:00, Бен Томпсон <b.thompson@latera.ru> wrote:
Sorry, my previous email was not formatted correctly.
Everyone, I have a problem and would would be grateful if you could have a quick look at it for me. I am trying to use the Option 82 data from a DHCP request, but for some reason the Circuit ID is changing during the processing of the request.
Here is the reqest coming in and then getting processed by the linelog module:
Received DHCP-Request of id 721fc604 from 10.180.1.1:67 to 10.160.0.254:67 0: 01 01 06 01 72 1f c6 04 00 a5 00 00 0a b4 01 05 16: 00 00 00 00 00 00 00 00 0a b4 01 01 50 af 73 18 32: ed 98 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 03 0c 07 73 75 70 70 6f 72 74 37 0d 01 1c 256: 02 03 0f 06 77 0c 2c 2f 1a 79 2a 52 12 01 08 00 272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 1 DHCP-Transaction-Id = 1914684932 DHCP-Number-of-Seconds = 165 DHCP-Flags = 0 DHCP-Client-IP-Address = 10.180.1.5 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 10.180.1.1 DHCP-Client-Hardware-Address = 50:af:73:18:ed:98 DHCP-Message-Type += DHCP-Request DHCP-Hostname += 'support' DHCP-Parameter-Request-List += DHCP-Subnet-Mask DHCP-Parameter-Request-List += DHCP-Broadcast-Address DHCP-Parameter-Request-List += DHCP-Time-Offset DHCP-Parameter-Request-List += DHCP-Router-Address DHCP-Parameter-Request-List += DHCP-Domain-Name DHCP-Parameter-Request-List += DHCP-Domain-Name-Server DHCP-Parameter-Request-List += DHCP-Domain-Search DHCP-Parameter-Request-List += DHCP-Hostname DHCP-Parameter-Request-List += DHCP-NETBIOS-Name-Servers DHCP-Parameter-Request-List += DHCP-NETBIOS DHCP-Parameter-Request-List += DHCP-Interface-MTU-Size DHCP-Parameter-Request-List += DHCP-Classless-Static-Route DHCP-Parameter-Request-List += DHCP-NTP-Servers DHCP-Relay-Circuit-Id = 0x000604b101000001 Mon Feb 24 16:51:36 2014 : Debug: Trying sub-section dhcp DHCP-Request {...} Mon Feb 24 16:51:36 2014 : Debug: (0) dhcp DHCP-Request { Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: calling linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: %{%{reply:DHCP-Message-Type}:- %{request:DHCP-Message-Type}} Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: if { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 2 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: else { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}" -> 'DHCP-Request' Mon Feb 24 16:51:36 2014 : Debug: /usr/local/var/log/radius/linelog-dhcp.log Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal: '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "/usr/local/var/log/radius/linelog-dhcp.log" -> '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: %S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ... Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal (with %): 'S' Mon Feb 24 16:51:36 2014 : Debug: literal: ' --> Transaction-ID: ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Transaction-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' REQUEST: [' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Client-Hardware-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '] via (' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Gateway-IP-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '), hop count = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Hop-Count Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ', Relay = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Remote-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' / ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Circuit-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' ...' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ..." -> '2014-02-24 16:51:36 --> Transaction-ID: 1914684932 REQUEST: [50:af:73:18:ed:98] via (10.180.1.1), hop count = 1, Relay = 0x00030f1ae32c / 0x5d20766961202800 ...' Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: returned from linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: (0) [linelog-dhcp] = ok
As you can see, the attribute DHCP-Relay-Circuit-Id starts of with value "0x000604b101000001" but by the time it is processed by linelog it has value "0x5d20766961202800"
Here is the full debug output: http://pastebin.com/b9RXPRD0
On 24 February 2014 21:28, Бен Томпсон <b.thompson@latera.ru> wrote:
olks, I have hit a problem and would would be grateful if you could have a quick look at it for me. I am trying to use the Option 82 data from a DHCP request, but for some reason the Circuit ID is changing during the procession for the request.
Here is the reqest coming in and then getting processed by the linelog module:
Received DHCP-Request of id 721fc604 from 10.180.1.1:67 to 10.160.0.254:67 0: 01 01 06 01 72 1f c6 04 00 a5 00 00 0a b4 01 05 16: 00 00 00 00 00 00 00 00 0a b4 01 01 50 af 73 18 32: ed 98 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 03 0c 07 73 75 70 70 6f 72 74 37 0d 01 1c 256: 02 03 0f 06 77 0c 2c 2f 1a 79 2a 52 12 01 08 00 272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 1 DHCP-Transaction-Id = 1914684932 DHCP-Number-of-Seconds = 165 DHCP-Flags = 0 DHCP-Client-IP-Address = 10.180.1.5 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 10.180.1.1 DHCP-Client-Hardware-Address = 50:af:73:18:ed:98 DHCP-Message-Type += DHCP-Request DHCP-Hostname += 'support' DHCP-Parameter-Request-List += DHCP-Subnet-Mask DHCP-Parameter-Request-List += DHCP-Broadcast-Address DHCP-Parameter-Request-List += DHCP-Time-Offset DHCP-Parameter-Request-List += DHCP-Router-Address DHCP-Parameter-Request-List += DHCP-Domain-Name DHCP-Parameter-Request-List += DHCP-Domain-Name-Server DHCP-Parameter-Request-List += DHCP-Domain-Search DHCP-Parameter-Request-List += DHCP-Hostname DHCP-Parameter-Request-List += DHCP-NETBIOS-Name-Servers DHCP-Parameter-Request-List += DHCP-NETBIOS DHCP-Parameter-Request-List += DHCP-Interface-MTU-Size DHCP-Parameter-Request-List += DHCP-Classless-Static-Route DHCP-Parameter-Request-List += DHCP-NTP-Servers DHCP-Relay-Circuit-Id = 0x000604b101000001 Mon Feb 24 16:51:36 2014 : Debug: Trying sub-section dhcp DHCP-Request {...} Mon Feb 24 16:51:36 2014 : Debug: (0) dhcp DHCP-Request { Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: calling linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: %{%{reply:DHCP-Message-Type}:- %{request:DHCP-Message-Type}} Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: if { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 2 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: else { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}" -> 'DHCP-Request' Mon Feb 24 16:51:36 2014 : Debug: /usr/local/var/log/radius/linelog-dhcp.log Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal: '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "/usr/local/var/log/radius/linelog-dhcp.log" -> '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: %S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ... Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal (with %): 'S' Mon Feb 24 16:51:36 2014 : Debug: literal: ' --> Transaction-ID: ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Transaction-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' REQUEST: [' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Client-Hardware-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '] via (' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Gateway-IP-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '), hop count = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Hop-Count Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ', Relay = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Remote-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' / ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Circuit-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' ...' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ..." -> '2014-02-24 16:51:36 --> Transaction-ID: 1914684932 REQUEST: [50:af:73:18:ed:98] via (10.180.1.1), hop count = 1, Relay = 0x00030f1ae32c / 0x5d20766961202800 ...' Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: returned from linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: (0) [linelog-dhcp] = ok
As you can see, the attribute DHCP-Relay-Circuit-Id starts of with value "0x000604b101000001" but by the time it is processed by linelog it has value "0x5d20766961202800"
Here is the full debug output: http://pastebin.com/b9RXPRD0
On 21 February 2014 19:02, Бен Томпсон <b.thompson@latera.ru> wrote:
Thanks for the info. It is looking better with 3.0.1. I will share my oracle configs once I have proved that they work.
On 21 February 2014 16:41, Alan DeKok <aland@deployingradius.com> wrote:
Бен Томпсон wrote:
radiusd: FreeRADIUS Version 3.1.0 (git #10ffd5b), for host
Don't use the "master" branch. Use an official release.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru
тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru
тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru
тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
Hello everyone, I decided to try the latest version from branch v3.0.x. However, the problem remains and the circuit ID is somehow lost during the processing of the request. Please let me know what do. I suppose I should create a bug report. Here is the relevant output from v3.0.x: Received DHCP-Discover of id fa86ba10 from 10.180.1.1:67 to 10.160.0.254:67 0: 01 01 06 01 fa 86 ba 10 00 08 00 00 00 00 00 00 16: 00 00 00 00 00 00 00 00 0a b4 01 01 50 af 73 18 32: ed 98 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 01 0c 07 73 75 70 70 6f 72 74 37 0d 01 1c 256: 02 03 0f 06 77 0c 2c 2f 1a 79 2a 52 12 01 08 00 272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 1 DHCP-Transaction-Id = 4203133456 DHCP-Number-of-Seconds = 8 DHCP-Flags = 0 DHCP-Client-IP-Address = 0.0.0.0 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 10.180.1.1 DHCP-Client-Hardware-Address = 50:af:73:18:ed:98 DHCP-Message-Type += DHCP-Discover DHCP-Hostname += 'support' DHCP-Parameter-Request-List += DHCP-Subnet-Mask DHCP-Parameter-Request-List += DHCP-Broadcast-Address DHCP-Parameter-Request-List += DHCP-Time-Offset DHCP-Parameter-Request-List += DHCP-Router-Address DHCP-Parameter-Request-List += DHCP-Domain-Name DHCP-Parameter-Request-List += DHCP-Domain-Name-Server DHCP-Parameter-Request-List += DHCP-Domain-Search DHCP-Parameter-Request-List += DHCP-Hostname DHCP-Parameter-Request-List += DHCP-NETBIOS-Name-Servers DHCP-Parameter-Request-List += DHCP-NETBIOS DHCP-Parameter-Request-List += DHCP-Interface-MTU-Size DHCP-Parameter-Request-List += DHCP-Classless-Static-Route DHCP-Parameter-Request-List += DHCP-NTP-Servers DHCP-Relay-Circuit-Id = 0x000604b101000001 Thu Feb 27 09:53:15 2014 : Debug: Trying sub-section dhcp DHCP-Discover {...} Thu Feb 27 09:53:15 2014 : Debug: (1) dhcp DHCP-Discover { Thu Feb 27 09:53:15 2014 : Debug: (1) modsingle[post-auth]: calling linelog-dhcp (rlm_linelog) for request 1 Thu Feb 27 09:53:15 2014 : Debug: %{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}} Thu Feb 27 09:53:15 2014 : Debug: Parsed xlat tree: Thu Feb 27 09:53:15 2014 : Debug: if { Thu Feb 27 09:53:15 2014 : Debug: attribute: DHCP-Message-Type Thu Feb 27 09:53:15 2014 : Debug: { Thu Feb 27 09:53:15 2014 : Debug: ref 2 Thu Feb 27 09:53:15 2014 : Debug: list 2 Thu Feb 27 09:53:15 2014 : Debug: tag -128 Thu Feb 27 09:53:15 2014 : Debug: } Thu Feb 27 09:53:15 2014 : Debug: } Thu Feb 27 09:53:15 2014 : Debug: else { Thu Feb 27 09:53:15 2014 : Debug: attribute: DHCP-Message-Type Thu Feb 27 09:53:15 2014 : Debug: { Thu Feb 27 09:53:15 2014 : Debug: ref 2 Thu Feb 27 09:53:15 2014 : Debug: list 1 Thu Feb 27 09:53:15 2014 : Debug: tag -128 Thu Feb 27 09:53:15 2014 : Debug: } Thu Feb 27 09:53:15 2014 : Debug: } Thu Feb 27 09:53:15 2014 : Debug: (1) linelog-dhcp : expand: "%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}" -> 'DHCP-Discover' Thu Feb 27 09:53:15 2014 : Debug: /usr/local/var/log/radius/linelog-dhcp.log Thu Feb 27 09:53:15 2014 : Debug: Parsed xlat tree: Thu Feb 27 09:53:15 2014 : Debug: literal: '/usr/local/var/log/radius/linelog-dhcp.log' Thu Feb 27 09:53:15 2014 : Debug: (1) linelog-dhcp : expand: "/usr/local/var/log/radius/linelog-dhcp.log" -> '/usr/local/var/log/radius/linelog-dhcp.log' Thu Feb 27 09:53:15 2014 : Debug: %S --> Transaction-ID: %{DHCP-Transaction-Id} DISCOVER: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id}, Hostname = %{DHCP-Hostname} Thu Feb 27 09:53:15 2014 : Debug: Parsed xlat tree: Thu Feb 27 09:53:15 2014 : Debug: literal (with %): 'S' Thu Feb 27 09:53:15 2014 : Debug: literal: ' --> Transaction-ID: ' Thu Feb 27 09:53:15 2014 : Debug: attribute: DHCP-Transaction-Id Thu Feb 27 09:53:15 2014 : Debug: { Thu Feb 27 09:53:15 2014 : Debug: ref 2 Thu Feb 27 09:53:15 2014 : Debug: list 1 Thu Feb 27 09:53:15 2014 : Debug: tag -128 Thu Feb 27 09:53:15 2014 : Debug: } Thu Feb 27 09:53:15 2014 : Debug: literal: ' DISCOVER: [' Thu Feb 27 09:53:15 2014 : Debug: attribute: DHCP-Client-Hardware-Address Thu Feb 27 09:53:15 2014 : Debug: { Thu Feb 27 09:53:15 2014 : Debug: ref 2 Thu Feb 27 09:53:15 2014 : Debug: list 1 Thu Feb 27 09:53:15 2014 : Debug: tag -128 Thu Feb 27 09:53:15 2014 : Debug: } Thu Feb 27 09:53:15 2014 : Debug: literal: '] via (' Thu Feb 27 09:53:15 2014 : Debug: attribute: DHCP-Gateway-IP-Address Thu Feb 27 09:53:15 2014 : Debug: { Thu Feb 27 09:53:15 2014 : Debug: ref 2 Thu Feb 27 09:53:15 2014 : Debug: list 1 Thu Feb 27 09:53:15 2014 : Debug: tag -128 Thu Feb 27 09:53:15 2014 : Debug: } Thu Feb 27 09:53:15 2014 : Debug: literal: '), hop count = ' Thu Feb 27 09:53:15 2014 : Debug: attribute: DHCP-Hop-Count Thu Feb 27 09:53:15 2014 : Debug: { Thu Feb 27 09:53:15 2014 : Debug: ref 2 Thu Feb 27 09:53:15 2014 : Debug: list 1 Thu Feb 27 09:53:15 2014 : Debug: tag -128 Thu Feb 27 09:53:15 2014 : Debug: } Thu Feb 27 09:53:15 2014 : Debug: literal: ', Relay = ' Thu Feb 27 09:53:15 2014 : Debug: attribute: DHCP-Relay-Remote-Id Thu Feb 27 09:53:15 2014 : Debug: { Thu Feb 27 09:53:15 2014 : Debug: ref 2 Thu Feb 27 09:53:15 2014 : Debug: list 1 Thu Feb 27 09:53:15 2014 : Debug: tag -128 Thu Feb 27 09:53:15 2014 : Debug: } Thu Feb 27 09:53:15 2014 : Debug: literal: ' / ' Thu Feb 27 09:53:15 2014 : Debug: attribute: DHCP-Relay-Circuit-Id Thu Feb 27 09:53:15 2014 : Debug: { Thu Feb 27 09:53:15 2014 : Debug: ref 2 Thu Feb 27 09:53:15 2014 : Debug: list 1 Thu Feb 27 09:53:15 2014 : Debug: tag -128 Thu Feb 27 09:53:15 2014 : Debug: } Thu Feb 27 09:53:15 2014 : Debug: literal: ', Hostname = ' Thu Feb 27 09:53:15 2014 : Debug: attribute: DHCP-Hostname Thu Feb 27 09:53:15 2014 : Debug: { Thu Feb 27 09:53:15 2014 : Debug: ref 2 Thu Feb 27 09:53:15 2014 : Debug: list 1 Thu Feb 27 09:53:15 2014 : Debug: tag -128 Thu Feb 27 09:53:15 2014 : Debug: } Thu Feb 27 09:53:15 2014 : Debug: (1) linelog-dhcp : expand: "%S --> Transaction-ID: %{DHCP-Transaction-Id} DISCOVER: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id}, Hostname = %{DHCP-Hostname}" -> '2014-02-27 09:53:15 --> Transaction-ID: 4203133456 DISCOVER: [50:af:73:18:ed:98] via (10.180.1.1), hop count = 1, Relay = 0x00030f1ae32c / 0x202f200000000000, Hostname = support' Thu Feb 27 09:53:15 2014 : Debug: (1) modsingle[post-auth]: returned from linelog-dhcp (rlm_linelog) for request 1 Thu Feb 27 09:53:15 2014 : Debug: (1) [linelog-dhcp] = ok Thu Feb 27 09:53:15 2014 : Debug: (1) update reply { Thu Feb 27 09:53:15 2014 : Debug: (1) DHCP-Flags = 0 Thu Feb 27 09:53:15 2014 : Debug: (1) } # update reply = noop Note that the value 0x202f200000000000 for circuit id is not correct. On 26 February 2014 17:17, Бен Томпсон <b.thompson@latera.ru> wrote:
Folks, I also noticed that the attribute DHCP-Relay-Remote-Id is not printed underneath the hex dumpbelow:
Received DHCP-Request of id 721fc604 from 10.180.1.1:67 to 10.160.0.254:67 0: 01 01 06 01 72 1f c6 04 00 a5 00 00 0a b4 01 05 16: 00 00 00 00 00 00 00 00 0a b4 01 01 50 af 73 18 32: ed 98 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 03 0c 07 73 75 70 70 6f 72 74 37 0d 01 1c 256: 02 03 0f 06 77 0c 2c 2f 1a 79 2a 52 12 01 08 00 272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 1 DHCP-Transaction-Id = 1914684932 DHCP-Number-of-Seconds = 165 DHCP-Flags = 0 DHCP-Client-IP-Address = 10.180.1.5 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 10.180.1.1 DHCP-Client-Hardware-Address = 50:af:73:18:ed:98 DHCP-Message-Type += DHCP-Request DHCP-Hostname += 'support' DHCP-Parameter-Request-List += DHCP-Subnet-Mask DHCP-Parameter-Request-List += DHCP-Broadcast-Address DHCP-Parameter-Request-List += DHCP-Time-Offset DHCP-Parameter-Request-List += DHCP-Router-Address DHCP-Parameter-Request-List += DHCP-Domain-Name DHCP-Parameter-Request-List += DHCP-Domain-Name-Server DHCP-Parameter-Request-List += DHCP-Domain-Search DHCP-Parameter-Request-List += DHCP-Hostname DHCP-Parameter-Request-List += DHCP-NETBIOS-Name-Servers DHCP-Parameter-Request-List += DHCP-NETBIOS DHCP-Parameter-Request-List += DHCP-Interface-MTU-Size DHCP-Parameter-Request-List += DHCP-Classless-Static-Route DHCP-Parameter-Request-List += DHCP-NTP-Servers DHCP-Relay-Circuit-Id = 0x000604b101000001 Mon Feb 24 16:51:36 2014 : Debug: Trying sub-section dhcp DHCP-Request {...}
It can be seen the the hex dump contains both Cicuit-Id (06 04 b1 01 00 00 01) and Remote-Id (00 03 0f 1a e3 2c):
272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff
But these are not printed underneath. If I can help to debug this please let me know what to do.
Thanks
Ben
On 25 February 2014 07:00, Бен Томпсон <b.thompson@latera.ru> wrote:
Sorry, my previous email was not formatted correctly.
Everyone, I have a problem and would would be grateful if you could have a quick look at it for me. I am trying to use the Option 82 data from a DHCP request, but for some reason the Circuit ID is changing during the processing of the request.
Here is the reqest coming in and then getting processed by the linelog module:
Received DHCP-Request of id 721fc604 from 10.180.1.1:67 to 10.160.0.254:67 0: 01 01 06 01 72 1f c6 04 00 a5 00 00 0a b4 01 05 16: 00 00 00 00 00 00 00 00 0a b4 01 01 50 af 73 18 32: ed 98 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 03 0c 07 73 75 70 70 6f 72 74 37 0d 01 1c 256: 02 03 0f 06 77 0c 2c 2f 1a 79 2a 52 12 01 08 00 272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 1 DHCP-Transaction-Id = 1914684932 DHCP-Number-of-Seconds = 165 DHCP-Flags = 0 DHCP-Client-IP-Address = 10.180.1.5 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 10.180.1.1 DHCP-Client-Hardware-Address = 50:af:73:18:ed:98 DHCP-Message-Type += DHCP-Request DHCP-Hostname += 'support' DHCP-Parameter-Request-List += DHCP-Subnet-Mask DHCP-Parameter-Request-List += DHCP-Broadcast-Address DHCP-Parameter-Request-List += DHCP-Time-Offset DHCP-Parameter-Request-List += DHCP-Router-Address DHCP-Parameter-Request-List += DHCP-Domain-Name DHCP-Parameter-Request-List += DHCP-Domain-Name-Server DHCP-Parameter-Request-List += DHCP-Domain-Search DHCP-Parameter-Request-List += DHCP-Hostname DHCP-Parameter-Request-List += DHCP-NETBIOS-Name-Servers DHCP-Parameter-Request-List += DHCP-NETBIOS DHCP-Parameter-Request-List += DHCP-Interface-MTU-Size DHCP-Parameter-Request-List += DHCP-Classless-Static-Route DHCP-Parameter-Request-List += DHCP-NTP-Servers DHCP-Relay-Circuit-Id = 0x000604b101000001 Mon Feb 24 16:51:36 2014 : Debug: Trying sub-section dhcp DHCP-Request {...} Mon Feb 24 16:51:36 2014 : Debug: (0) dhcp DHCP-Request { Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: calling linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: %{%{reply:DHCP-Message-Type}:- %{request:DHCP-Message-Type}} Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: if { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 2 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: else { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}" -> 'DHCP-Request' Mon Feb 24 16:51:36 2014 : Debug: /usr/local/var/log/radius/linelog-dhcp.log Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal: '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "/usr/local/var/log/radius/linelog-dhcp.log" -> '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: %S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ... Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal (with %): 'S' Mon Feb 24 16:51:36 2014 : Debug: literal: ' --> Transaction-ID: ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Transaction-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' REQUEST: [' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Client-Hardware-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '] via (' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Gateway-IP-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '), hop count = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Hop-Count Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ', Relay = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Remote-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' / ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Circuit-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' ...' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ..." -> '2014-02-24 16:51:36 --> Transaction-ID: 1914684932 REQUEST: [50:af:73:18:ed:98] via (10.180.1.1), hop count = 1, Relay = 0x00030f1ae32c / 0x5d20766961202800 ...' Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: returned from linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: (0) [linelog-dhcp] = ok
As you can see, the attribute DHCP-Relay-Circuit-Id starts of with value "0x000604b101000001" but by the time it is processed by linelog it has value "0x5d20766961202800"
Here is the full debug output: http://pastebin.com/b9RXPRD0
On 24 February 2014 21:28, Бен Томпсон <b.thompson@latera.ru> wrote:
olks, I have hit a problem and would would be grateful if you could have a quick look at it for me. I am trying to use the Option 82 data from a DHCP request, but for some reason the Circuit ID is changing during the procession for the request.
Here is the reqest coming in and then getting processed by the linelog module:
Received DHCP-Request of id 721fc604 from 10.180.1.1:67 to 10.160.0.254:67 0: 01 01 06 01 72 1f c6 04 00 a5 00 00 0a b4 01 05 16: 00 00 00 00 00 00 00 00 0a b4 01 01 50 af 73 18 32: ed 98 00 00 00 00 00 00 00 00 00 00 00 00 00 00 48: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 64: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 96: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 112: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 128: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 144: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 160: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 176: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 192: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 208: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 224: 00 00 00 00 00 00 00 00 00 00 00 00 63 82 53 63 240: 35 01 03 0c 07 73 75 70 70 6f 72 74 37 0d 01 1c 256: 02 03 0f 06 77 0c 2c 2f 1a 79 2a 52 12 01 08 00 272: 06 04 b1 01 00 00 01 02 06 00 03 0f 1a e3 2c ff 288: 00 00 00 00 00 00 00 00 00 00 00 00 DHCP-Opcode = Client-Message DHCP-Hardware-Type = Ethernet DHCP-Hardware-Address-Length = 6 DHCP-Hop-Count = 1 DHCP-Transaction-Id = 1914684932 DHCP-Number-of-Seconds = 165 DHCP-Flags = 0 DHCP-Client-IP-Address = 10.180.1.5 DHCP-Your-IP-Address = 0.0.0.0 DHCP-Server-IP-Address = 0.0.0.0 DHCP-Gateway-IP-Address = 10.180.1.1 DHCP-Client-Hardware-Address = 50:af:73:18:ed:98 DHCP-Message-Type += DHCP-Request DHCP-Hostname += 'support' DHCP-Parameter-Request-List += DHCP-Subnet-Mask DHCP-Parameter-Request-List += DHCP-Broadcast-Address DHCP-Parameter-Request-List += DHCP-Time-Offset DHCP-Parameter-Request-List += DHCP-Router-Address DHCP-Parameter-Request-List += DHCP-Domain-Name DHCP-Parameter-Request-List += DHCP-Domain-Name-Server DHCP-Parameter-Request-List += DHCP-Domain-Search DHCP-Parameter-Request-List += DHCP-Hostname DHCP-Parameter-Request-List += DHCP-NETBIOS-Name-Servers DHCP-Parameter-Request-List += DHCP-NETBIOS DHCP-Parameter-Request-List += DHCP-Interface-MTU-Size DHCP-Parameter-Request-List += DHCP-Classless-Static-Route DHCP-Parameter-Request-List += DHCP-NTP-Servers DHCP-Relay-Circuit-Id = 0x000604b101000001 Mon Feb 24 16:51:36 2014 : Debug: Trying sub-section dhcp DHCP-Request {...} Mon Feb 24 16:51:36 2014 : Debug: (0) dhcp DHCP-Request { Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: calling linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: %{%{reply:DHCP-Message-Type}:- %{request:DHCP-Message-Type}} Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: if { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 2 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: else { Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Message-Type Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%{%{reply:DHCP-Message-Type}:-%{request:DHCP-Message-Type}}" -> 'DHCP-Request' Mon Feb 24 16:51:36 2014 : Debug: /usr/local/var/log/radius/linelog-dhcp.log Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal: '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "/usr/local/var/log/radius/linelog-dhcp.log" -> '/usr/local/var/log/radius/linelog-dhcp.log' Mon Feb 24 16:51:36 2014 : Debug: %S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ... Mon Feb 24 16:51:36 2014 : Debug: Parsed xlat tree: Mon Feb 24 16:51:36 2014 : Debug: literal (with %): 'S' Mon Feb 24 16:51:36 2014 : Debug: literal: ' --> Transaction-ID: ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Transaction-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' REQUEST: [' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Client-Hardware-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '] via (' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Gateway-IP-Address Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: '), hop count = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Hop-Count Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ', Relay = ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Remote-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' / ' Mon Feb 24 16:51:36 2014 : Debug: attribute: DHCP-Relay-Circuit-Id Mon Feb 24 16:51:36 2014 : Debug: { Mon Feb 24 16:51:36 2014 : Debug: ref 2 Mon Feb 24 16:51:36 2014 : Debug: list 1 Mon Feb 24 16:51:36 2014 : Debug: tag -128 Mon Feb 24 16:51:36 2014 : Debug: } Mon Feb 24 16:51:36 2014 : Debug: literal: ' ...' Mon Feb 24 16:51:36 2014 : Debug: (0) linelog-dhcp : expand: "%S --> Transaction-ID: %{DHCP-Transaction-Id} REQUEST: [%{DHCP-Client-Hardware-Address}] via (%{DHCP-Gateway-IP-Address}), hop count = %{DHCP-Hop-Count}, Relay = %{DHCP-Relay-Remote-Id} / %{DHCP-Relay-Circuit-Id} ..." -> '2014-02-24 16:51:36 --> Transaction-ID: 1914684932 REQUEST: [50:af:73:18:ed:98] via (10.180.1.1), hop count = 1, Relay = 0x00030f1ae32c / 0x5d20766961202800 ...' Mon Feb 24 16:51:36 2014 : Debug: (0) modsingle[post-auth]: returned from linelog-dhcp (rlm_linelog) for request 0 Mon Feb 24 16:51:36 2014 : Debug: (0) [linelog-dhcp] = ok
As you can see, the attribute DHCP-Relay-Circuit-Id starts of with value "0x000604b101000001" but by the time it is processed by linelog it has value "0x5d20766961202800"
Here is the full debug output: http://pastebin.com/b9RXPRD0
On 21 February 2014 19:02, Бен Томпсон <b.thompson@latera.ru> wrote:
Thanks for the info. It is looking better with 3.0.1. I will share my oracle configs once I have proved that they work.
On 21 February 2014 16:41, Alan DeKok <aland@deployingradius.com>wrote:
Бен Томпсон wrote:
radiusd: FreeRADIUS Version 3.1.0 (git #10ffd5b), for host
Don't use the "master" branch. Use an official release.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru
тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru
тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru
тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
On 27 Feb 2014, at 05:59, Бен Томпсон <b.thompson@latera.ru> wrote:
Hello everyone, I decided to try the latest version from branch v3.0.x. However, the problem remains and the circuit ID is somehow lost during the processing of the request. Please let me know what do. I suppose I should create a bug report.
Yes on bugs.freeradius.org. Could you also provide a .pcap of the DHCP-Discover. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Thanks Arran. Here is the ticket: https://github.com/FreeRADIUS/freeradius-server/issues/536 On 27 February 2014 13:32, Arran Cudbard-Bell <a.cudbardb@freeradius.org>wrote:
On 27 Feb 2014, at 05:59, Бен Томпсон <b.thompson@latera.ru> wrote:
Hello everyone, I decided to try the latest version from branch v3.0.x. However, the problem remains and the circuit ID is somehow lost during the processing of the request. Please let me know what do. I suppose I should create a bug report.
Yes on bugs.freeradius.org. Could you also provide a .pcap of the DHCP-Discover.
-Arran
Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team
FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Бен Томпсон, инженер отдела внедрения и техподдержки, компания "Латера" | www.latera.ru тел.: +7 (499) 940-95-05, доб. 221 E-mail: b.thompson@latera.ru
participants (3)
-
Alan DeKok -
Arran Cudbard-Bell -
Бен Томпсон