Reporting from logs

Tue Sep 25 16:34:42 CEST 2012

Hi,

On Tue, Sep 25, 2012 at 03:00:26PM +0100, Phil Mayers wrote:
> On 25/09/12 14:39, Matthew Newton wrote:
> How do you relay post-auth? That's one of the main reasons we still
> use rlm_sql_log, as opposed to the built in "detail" listener.

Pure total hackery.

linelog can include '\n' in the output so can simlulate the detail
module for given attributes. The relayed auth packets are sent on
the wire as acct packets...

on the main servers, in default (and inner-tunnel, except post-auth-type reject
doesn't work there):

post-auth {
  ...
  relay_detail_auth
  ...
  Post-Auth-Type REJECT {
    ...
    relay_detail_auth
    ...
  }
}

in modules/linelog:

linelog relay_detail_auth {
        filename = ${radacctdir}/relay-detail
   ## ^^^^ this is read by copy-acct-to-home-server, and also written to by
   ## detail for accounting packets as usual

        reference = "%{%{reply:Packet-Type}:-format}"

        format = "%t\n\tPacket-Type = %{reply:Packet-Type}\n\tUser-Name = \"%{User-Name}\"\n\tNAS-IP-Address = %{NAS-IP-Address}\n\tCalling-Station-Id = \"%{Calling-Station-Id}\"\n\tCalled-Station-Id = \"%{Called-Station-ID}\"\n\tNAS-Identifier = \"%{NAS-Identifier}\"\n\tRealm = %{request:Realm}\n\tAirespace-Wlan-Id = %{Airespace-Wlan-Id}\n\tTunnel-Type:0 = %{Tunnel-Type}\n\tTunnel-Medium-Type:0 = %{Tunnel-Medium-Type}\n\tTunnel-Private-Group-Id:0 = \"%{Tunnel-Private-Group-Id}\"\n\tHuntgroup-Name = %{Huntgroup-Name}\n\tUoL-Log-Packet-Date = \"%t\"\n\tUoL-Log-Client-IP = \"%{Client-IP-Address}\"\n\tUoL-Log-Realm = %{Realm}\n\tOperator-Name = \"%{Operator-Name}\"\n"

        Access-Accept = "%t\n\tPacket-Type = %{reply:Packet-Type}\n\tUser-Name = \"%{User-Name}\"\n\tNAS-IP-Address = %{NAS-IP-Address}\n\tCalling-Station-Id = \"%{Calling-Station-Id}\"\n\tCalled-Station-Id = \"%{Called-Station-ID}\"\n\tNAS-Identifier = \"%{NAS-Identifier}\"\n\tRealm = %{request:Realm}\n\tAirespace-Wlan-Id = %{Airespace-Wlan-Id}\n\tTunnel-Type:0 = %{Tunnel-Type}\n\tTunnel-Medium-Type:0 = %{Tunnel-Medium-Type}\n\tTunnel-Private-Group-Id:0 = \"%{Tunnel-Private-Group-Id}\"\n\tHuntgroup-Name = %{Huntgroup-Name}\n\tUoL-Log-Packet-Date = \"%t\"\n\tUoL-Log-Client-IP = \"%{Client-IP-Address}\"\n\tUoL-Log-Packet-Type = Auth-Access-Accept\n\tUoL-Log-Realm = %{Realm}\n\tOperator-Name = \"%{Operator-Name}\"\n"

        Access-Reject = "%t\n\tPacket-Type = %{reply:Packet-Type}\n\tUser-Name = \"%{User-Name}\"\n\tNAS-IP-Address = %{NAS-IP-Address}\n\tCalling-Station-Id = \"%{Calling-Station-Id}\"\n\tCalled-Station-Id = \"%{Called-Station-ID}\"\n\tNAS-Identifier = \"%{NAS-Identifier}\"\n\tRealm = %{request:Realm}\n\tAirespace-Wlan-Id = %{Airespace-Wlan-Id}\n\tTunnel-Type:0 = %{Tunnel-Type}\n\tTunnel-Medium-Type:0 = %{Tunnel-Medium-Type}\n\tTunnel-Private-Group-Id:0 = \"%{Tunnel-Private-Group-Id}\"\n\tHuntgroup-Name = %{Huntgroup-Name}\n\tUoL-Log-Packet-Date = \"%t\"\n\tUoL-Log-Client-IP = \"%{Client-IP-Address}\"\n\tUoL-Log-Packet-Type = Auth-Access-Reject\n\tUoL-Log-Realm = %{Realm}\n\tOperator-Name = \"%{Operator-Name}\"\n"
}

in the dictionary:

VENDOR          Leicester               3385

BEGIN-VENDOR    Leicester

ATTRIBUTE       UoL-Log-Packet-Type             1       integer
ATTRIBUTE       UoL-Log-Packet-Date             2       string
ATTRIBUTE       UoL-Log-Client-IP               3       ipaddr
ATTRIBUTE       UoL-Log-Realm                   4       string
ATTRIBUTE       UoL-Log-Acct-Session-Id         5       string

VALUE           UoL-Log-Packet-Type             Auth-Access-Accept      0
VALUE           UoL-Log-Packet-Type             Auth-Access-Reject      1

END-VENDOR      Leicester

on the central logging server:

accounting {
  detail
  linelog_acct
  ...
}

The detail log gets everything in a good enough state to find out what happened
and on which RADIUS server. Then there's another hideous linelog instantiation:

linelog linelog_acct {
        filename = /srv/log/radius/radius-${hostname}-%D.log
        group = radlogs
        permissions = 0640

        format = "You should never see this log message for %{User-Name} with packet type %{Packet-Type} (linelog_acct) %{Operator-Name}"

        reference = "%{%{%{Acct-Status-Type}:-%{UoL-Log-Packet-Type}}:-format}"

        Start = "%t\t%{Client-IP-Address}\t%{UoL-Log-Client-IP}\tACCT Start\t%{Calling-Station-Id}\t%{UoL-Log-Realm}\t%{User-Name}\t%{NAS-Identifier}\t%{Called-Station-Id}\t%{Airespace-Wlan-Id}\t%{Tunnel-Private-Group-Id}\t%{Framed-IP-Address}\t%{%{Acct-Unique-Session-Id}:-%{UoL-Log-Acct-Session-Id}}\t%{Acct-Input-Octets}\t%{Acct-Output-Octets}\t%{Operator-Name}"
        Stop = "%t\t%{Client-IP-Address}\t%{UoL-Log-Client-IP}\tACCT Stop\t%{Calling-Station-Id}\t%{UoL-Log-Realm}\t%{User-Name}\t%{NAS-Identifier}\t%{Called-Station-Id}\t%{Airespace-Wlan-Id}\t%{Tunnel-Private-Group-Id}\t%{Framed-IP-Address}\t%{%{Acct-Unique-Session-Id}:-%{UoL-Log-Acct-Session-Id}}\t%{Acct-Input-Octets}\t%{Acct-Output-Octets}\t%{Operator-Name}"
        Interim-Update = "%t\t%{Client-IP-Address}\t%{UoL-Log-Client-IP}\tACCT Update\t%{Calling-Station-Id}\t%{UoL-Log-Realm}\t%{User-Name}\t%{NAS-Identifier}\t%{Called-Station-Id}\t%{Airespace-Wlan-Id}\t%{Tunnel-Private-Group-Id}\t%{Framed-IP-Address}\t%{%{Acct-Unique-Session-Id}:-%{UoL-Log-Acct-Session-Id}}\t%{Acct-Input-Octets}\t%{Acct-Output-Octets}\t%{Operator-Name}"

# UoL-Log-Packet-Type is set by the detail reader (radrelay) config, which is a copy of the Packet-Type for
# Auth packets (Access-Accept or Access-Reject are what we care about). If Acct-Status-Type is not set, then
# we check to see if this attribute is present instead, and log as an Auth packet. This should only happen on
# radman, not on the main radius servers.

        Auth-Access-Accept = "%{UoL-Log-Packet-Date}\t%{Client-IP-Address}\t%{UoL-Log-Client-IP}\tAUTH Accept\t%{Calling-Station-Id}\t%{UoL-Log-Realm}\t%{User-Name}\t%{NAS-Identifier}\t%{Called-Station-Id}\t%{Airespace-Wlan-Id}\t%{Tunnel-Private-Group-Id}\t%{Operator-Name}"
        Auth-Access-Reject = "%{UoL-Log-Packet-Date}\t%{Client-IP-Address}\t%{UoL-Log-Client-IP}\tAUTH Reject\t%{Calling-Station-Id}\t%{UoL-Log-Realm}\t%{User-Name}\t%{NAS-Identifier}\t%{Called-Station-Id}\t%{Airespace-Wlan-Id}\t%{Tunnel-Private-Group-Id}\t%{Operator-Name}"
}

This is also called on the main radius servers, so each system has
its own logs in /srv/log/radius/radius-${hostname}-%D.log by date.

The web interface and cron reports all just pull from these
linelogs. 95% of any looking at the logs happens on the central
server, and if more detail is needed then that tells us directly
which RADIUS server to go to to get the full detail logs.

My reason for avoiding SQL was because I didn't want an SQL
problem to slow down or stop the main RADIUS servers, either in
the event of database failure, or just database slowness. Writing
and reading files is fast. Now that this relays over, I am
thinking about putting SQL on the backend, and it doesn't matter
if it goes away as it all queues up in relay-detail files on the
live servers.

Note that it may not be good for anyone's sanity to actually try
and copy the above method...

Cheers,

Matthew

-- 
Matthew Newton, Ph.D. <mcn4 at le.ac.uk>

Systems Architect (UNIX and Networks), Network Services,
I.T. Services, University of Leicester, Leicester LE1 7RH, United Kingdom

For IT help contact helpdesk extn. 2253, <ithelp at le.ac.uk>