FreeRADIUS 3.0.12 VMPS and logging twice?

Václav Ovsík vaclav.ovsik at i.cz
Wed Jun 28 17:49:09 CEST 2017


Hi,
we are using FreeRADIUS VMPS server for a long time on Debian GNU/Linux.
It works perfectly and my tiny modification to dist vmps site
definition is line log. With FreeRADIUS 2.2.5 it worked fine. I did
upgrade of first VMPS yesterday (Debian Stretch) and did a small mods to
vmps for FreeRADIUS version 3.0.12.
What I didn't know to do with is that vmps processing doubled or
two-phase or something (every request is logged twice).

Request sent from monitoring site using check_vmps nagios plugin with success:

 VMPS OK - Vlan: TPS, MAC Address: d4bed9681558, Status: ALLOW

response is correct one packet (checked using tcpdump).
The output of freeradius -X:

 FreeRADIUS Version 3.0.12
 Copyright (C) 1999-2016 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/share/freeradius/dictionary
 including dictionary file /usr/share/freeradius/dictionary.dhcp
 including dictionary file /usr/share/freeradius/dictionary.vqp
 including dictionary file /etc/freeradius/3.0/dictionary
 including configuration file /etc/freeradius/3.0/radiusd.conf
 including configuration file /etc/freeradius/3.0/clients.conf
 including files in directory /etc/freeradius/3.0/mods-enabled/
 including configuration file /etc/freeradius/3.0/mods-enabled/mac2vlan
 including configuration file /etc/freeradius/3.0/mods-enabled/linelog_vmps
 including files in directory /etc/freeradius/3.0/policy.d/
 including configuration file /etc/freeradius/3.0/policy.d/control
 including configuration file /etc/freeradius/3.0/policy.d/canonicalization
 including configuration file /etc/freeradius/3.0/policy.d/eap
 including configuration file /etc/freeradius/3.0/policy.d/cui
 including configuration file /etc/freeradius/3.0/policy.d/dhcp
 including configuration file /etc/freeradius/3.0/policy.d/filter
 including configuration file /etc/freeradius/3.0/policy.d/accounting
 including configuration file /etc/freeradius/3.0/policy.d/abfab-tr
 including configuration file /etc/freeradius/3.0/policy.d/moonshot-targeted-ids
 including configuration file /etc/freeradius/3.0/policy.d/debug
 including configuration file /etc/freeradius/3.0/policy.d/operator-name
 including files in directory /etc/freeradius/3.0/sites-enabled/
 including configuration file /etc/freeradius/3.0/sites-enabled/vmps
 main {
  security {
  	user = "freerad"
  	group = "freerad"
  	allow_core_dumps = no
  }
 	name = "freeradius"
 	prefix = "/usr"
 	localstatedir = "/var"
 	logdir = "/var/log/freeradius"
 	run_dir = "/var/run/freeradius"
 }
 main {
 	name = "freeradius"
 	prefix = "/usr"
 	localstatedir = "/var"
 	sbindir = "/usr/sbin"
 	logdir = "/var/log/freeradius"
 	run_dir = "/var/run/freeradius"
 	libdir = "/usr/lib/freeradius"
 	radacctdir = "/var/log/freeradius/radacct"
 	hostname_lookups = no
 	max_request_time = 30
 	cleanup_delay = 5
 	max_requests = 16384
 	pidfile = "/var/run/freeradius/freeradius.pid"
 	checkrad = "/usr/sbin/checkrad"
 	debug_level = 0
 	proxy_requests = no
  log {
  	stripped_names = no
  	auth = no
  	auth_badpass = no
  	auth_goodpass = no
  	colourise = yes
  	msg_denied = "You are already logged in - access denied"
  }
  resources {
  }
  security {
  	max_attributes = 200
  	reject_delay = 1.000000
  	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
   }
  }
  client localhost_ipv6 {
  	ipv6addr = ::1
  	require_message_authenticator = no
  	secret = <<< secret >>>
   limit {
   	max_connections = 16
   	lifetime = 0
   	idle_timeout = 30
   }
  }
 Debugger not attached
 radiusd: #### Instantiating modules ####
  modules {
   # Loaded module rlm_passwd
   # Loading module "mac2vlan" from file /etc/freeradius/3.0/mods-enabled/mac2vlan
   passwd mac2vlan {
   	filename = "/etc/freeradius/3.0/mods-config/passwd/mac2vlan"
   	format = "*VMPS-Mac:=VMPS-VLAN-Name"
   	delimiter = ","
   	ignore_nislike = yes
   	ignore_empty = yes
   	allow_multiple_keys = no
   	hash_size = 100
   }
   # Loaded module rlm_linelog
   # Loading module "linelog_vmps" from file /etc/freeradius/3.0/mods-enabled/linelog_vmps
   linelog linelog_vmps {
   	filename = "/var/log/freeradius/vmps.log"
   	escape_filenames = no
   	syslog_severity = "info"
   	permissions = 384
   	format = "%S	%{VMPS-Client-IP-Address} %{VMPS-Port-Name}	%{VMPS-Packet-Type}	%{VMPS-Mac} -> %{reply:VMPS-VLAN-Name}"
   }
   instantiate {
   }
   # Instantiating module "mac2vlan" from file /etc/freeradius/3.0/mods-enabled/mac2vlan
 rlm_passwd: nfields: 2 keyfield 0(VMPS-Mac) listable: no
   # Instantiating module "linelog_vmps" from file /etc/freeradius/3.0/mods-enabled/linelog_vmps
  } # modules
 radiusd: #### Loading Virtual Servers ####
 server { # from file /etc/freeradius/3.0/radiusd.conf
 } # server
 server vmps { # from file /etc/freeradius/3.0/sites-enabled/vmps
  # Loading vmps {...}
 } # server vmps
 radiusd: #### Opening IP addresses and Ports ####
 listen {
   	type = "vmps"
   	ipaddr = 10.2.28.97
   	port = 1589
   client cisco-switches {
   	ipaddr = 192.168.0.0
   	netmask = 16
   	require_message_authenticator = no
   	secret = <<< secret >>>
    limit {
    	max_connections = 16
    	lifetime = 0
    	idle_timeout = 30
    }
   }
   client cisco-switches2 {
   	ipaddr = 10.0.0.0
   	netmask = 11
   	require_message_authenticator = no
   	secret = <<< secret >>>
    limit {
    	max_connections = 16
    	lifetime = 0
    	idle_timeout = 30
    }
   }
   client monit {
   	ipaddr = 192.168.30.80
   	netmask = 28
   	require_message_authenticator = no
   	secret = <<< secret >>>
    limit {
    	max_connections = 16
    	lifetime = 0
    	idle_timeout = 30
    }
   }
   client monit2 {
   	ipaddr = 10.0.156.80
   	netmask = 29
   	require_message_authenticator = no
   	secret = <<< secret >>>
    limit {
    	max_connections = 16
    	lifetime = 0
    	idle_timeout = 30
    }
   }
 }
 Listening on vmps address 10.2.28.97 port 1589 bound to server vmps
 Ready to process requests
 	VMPS-Packet-Type = VMPS-Join-Request
 	VMPS-Error-Code = VMPS-No-Error
 	VMPS-Sequence-Number = 4660
 	VMPS-Client-IP-Address = 127.0.0.1
 	VMPS-Port-Name = "Fa0/1"
 	VMPS-VLAN-Name = ""
 	VMPS-Domain-Name = ""
 	VMPS-Unknown = 0x00
 	VMPS-MAC = d4:be:d9:68:15:58
 (0) Received Access-Request Id 4660 from 192.168.30.82:41160 to 10.2.28.97:1589 length 60
 (0)   VMPS-Packet-Type = VMPS-Join-Request
 (0)   VMPS-Error-Code = VMPS-No-Error
 (0)   VMPS-Sequence-Number = 4660
 (0)   VMPS-Client-IP-Address = 127.0.0.1
 (0)   VMPS-Port-Name = "Fa0/1"
 (0)   VMPS-VLAN-Name = ""
 (0)   VMPS-Domain-Name = ""
 (0)   VMPS-Unknown = 0x00
 (0)   VMPS-MAC = d4:be:d9:68:15:58
 Doing VMPS
 (0)   vmps {
 (0)     if (!&VMPS-Mac) {
 (0)     if (!&VMPS-Mac)  -> FALSE
 (0) mac2vlan: Added VMPS-VLAN-Name: 'TPS' to reply_items 
 (0)     [mac2vlan] = ok
 (0)     update reply {
 (0)       &VMPS-Packet-Type = VMPS-Join-Response
 (0)       &VMPS-Cookie = &VMPS-Mac -> d4:be:d9:68:15:58
 (0)       &VMPS-VLAN-Name = "Guest"
 (0)     } # update reply = noop
 (0)     if (&VMPS-Packet-Type == VMPS-Reconfirm-Request){
 (0)     if (&VMPS-Packet-Type == VMPS-Reconfirm-Request) -> FALSE
 (0) linelog_vmps: EXPAND %S	%{VMPS-Client-IP-Address} %{VMPS-Port-Name}	%{VMPS-Packet-Type}	%{VMPS-Mac} -> %{reply:VMPS-VLAN-Name}
 (0) linelog_vmps:    --> 2017-06-28 17:21:53	127.0.0.1 Fa0/1	VMPS-Join-Request	d4:be:d9:68:15:58 -> TPS
 (0) linelog_vmps: EXPAND /var/log/freeradius/vmps.log
 (0) linelog_vmps:    --> /var/log/freeradius/vmps.log
 (0)     [linelog_vmps] = ok
 (0)   } # vmps = ok
 Done VMPS
 (0)   vmps {
 (0)     if (!&VMPS-Mac) {
 (0)     if (!&VMPS-Mac)  -> FALSE
 (0) mac2vlan: Added VMPS-VLAN-Name: 'TPS' to reply_items 
 (0)     [mac2vlan] = ok
 (0)     update reply {
 (0)       &VMPS-Packet-Type = VMPS-Join-Response
 (0)       &VMPS-Cookie = &VMPS-Mac -> d4:be:d9:68:15:58
 (0)       &VMPS-VLAN-Name = "Guest"
 (0)     } # update reply = noop
 (0)     if (&VMPS-Packet-Type == VMPS-Reconfirm-Request){
 (0)     if (&VMPS-Packet-Type == VMPS-Reconfirm-Request) -> FALSE
 (0) linelog_vmps: EXPAND %S	%{VMPS-Client-IP-Address} %{VMPS-Port-Name}	%{VMPS-Packet-Type}	%{VMPS-Mac} -> %{reply:VMPS-VLAN-Name}
 (0) linelog_vmps:    --> 2017-06-28 17:21:53	127.0.0.1 Fa0/1	VMPS-Join-Request	d4:be:d9:68:15:58 -> TPS
 (0) linelog_vmps: EXPAND /var/log/freeradius/vmps.log
 (0) linelog_vmps:    --> /var/log/freeradius/vmps.log
 (0)     [linelog_vmps] = ok
 (0)   } # vmps = ok
 (0) Sent Access-Accept Id 4660 from 10.2.28.97:1589 to 192.168.30.82:41160 length 0
 	VMPS-VLAN-Name = "TPS"
 	VMPS-Cookie = d4:be:d9:68:15:58
 (0) Finished request
 (0) Cleaning up request packet ID 4660 with timestamp +3
 Ready to process requests

To distributed Debian configuration I did only
 * disabled proxy_requests in radiusd.conf
 * added to site-enabled vmps, removed default and inner-tunnel
 * removed all mods from mods-enabled and enable linelog-vmps and
   mac2vlan
Any idea why there is second pass after 'Done VMPS'?
Regards
-- 
Zito


More information about the Freeradius-Users mailing list