10. Problem Tracking

10.1 Rule Tracing		Tracing rules.
10.2 Debugging		Enabling full debugging information.
10.3 Test Mode		Running radius in test mode.

10.1 Rule Tracing

If you have more than one entry in your `users' file it is not always obvious which of the entries were used for authentication. The authentication data flow becomes even harder to understand if there are some complex rules in the `hints' and `huntgroups' files.

The rule tracing mode is intended to help you find out the exact order of the rules that each request matched during processing. The mode is toggled by trace-rules statement in auth or acct block of your `config' file. When rule tracing mode is on for a given type of requests, radiusd will display the data flow diagram for each processed request of this type. The diagram is output on info logging category, it represents the list of rules in reverse chronological order. Each rule is represented by its location in the form filename:line. To make the output more compact, if several rules appear in the same configuration file, their locations are listed as a comma-separated list of numbers after the file name. Furthermore, if the configuration files have the same path prefix, then only the first file name appears with the full prefix.

Here is an example of trace rule diagram:

Oct 31 11:37:17 [28322]: Auth.info: (Access-Request foo 170 bar): rule trace: /etc/raddb/users:157,22,3; huntgroups:72; hints:34

This diagram means, that the authentication request from server `foo' for user `bar' with ID 170 matched the following rules

File name	Line number
`/etc/raddb/hints'	34
`/etc/raddb/huntgroups'	72
`/etc/raddb/users'	3
`/etc/raddb/users'	22
`/etc/raddb/users'	157

As a practical example, let's suppose you have the following setup. There are three classes of users:

1. Users from group "root" are authenticated using system password database and get rlogin access to the server 192.168.10.1
2. Users from group "staff" are also authenticated using system password database, but they are granted only telnet access to the server 192.168.10.2
3. Finally, the rest of users is authenticated against SQL database and get usual PPP access.

In addition, users from the first two classes are accounted using custom Scheme procedure staff-acct.

The configuration files for this setup are showed below:

Contents of `hints':

DEFAULT Group = "root" Scheme-Acct-Procedure = "staff-acct", Hint = "admin" DEFAULT Group = "staff" Scheme-Acct-Procedure = "staff-acct", Hint = "staff"

Contents of file `users':

DEFAULT Auth-Type = SQL, Simultaneous-Use = 1 Service-Type = Framed-User, Framed-Protocol = PPP DEFAULT Hint = "admin", Auth-Type = System Service-Type = Login-User, Login-IP-Host = 192.168.0.1, Login-Service = Rlogin DEFAULT Hint = "staff", Auth-Type = System, Simultaneous-Use = 1 Service-Type = Login-User, Login-IP-Host = 192.168.0.2, Login-Service = Telnet

Now, let's suppose that user `svp' is in the group `staff' and is trying to log in. However, he fails to do so and in radiusd logs you see:

Nov 06 21:25:24: Auth.notice: (Access-Request local 61 svp): Login incorrect [svp]

Why? To answer this question, you add to auth block of your `config' the statement

trace-rules yes;

and ask user `svp' to retry his attempt. Now you see in your logs:

Nov 06 21:31:24: Auth.notice: (Access-Request local 13 svp): Login incorrect [svp] Nov 06 21:31:24: Auth.info: (Access-Request local 13 svp): rule trace: /etc/raddb/users:1, hints: 5

This means that the request for `svp' has first matched rule on the line 1 of file `hints', then the rule on line 1 of file `users'. Now you see the error: the entries in `users' appear in wrong order! After fixing it your `users' looks like:

DEFAULT Hint = "admin", Auth-Type = System Service-Type = Login-User, Login-IP-Host = 192.168.0.1, Login-Service = Rlogin DEFAULT Hint = "staff", Auth-Type = System, Simultaneous-Use = 1 Service-Type = Login-User, Login-IP-Host = 192.168.0.2, Login-Service = Telnet DEFAULT Auth-Type = SQL, Simultaneous-Use = 1 Service-Type = Framed-User, Framed-Protocol = PPP

Now, you ask `svp' to log in again, and see:

Nov 06 21:35:14: Auth.notice: (Access-Request local 42 svp): Login OK [svp] Nov 06 21:35:14: Auth.info: (Access-Request local 42 svp): rule trace: /etc/raddb/users:7, hints: 5

Let's also suppose that user `plog' is not listed in groups "root" and "staff", so he is supposed to authenticate using SQL. When he logs in, you see in your logs:

Nov 06 21:39:05: Auth.notice: (Access-Request local 122 plog): Login OK [svp] Nov 06 21:39:05: Auth.info: (Access-Request local 122 plog): rule trace: /etc/raddb/users:14

10.2 Debugging

GNU Radius provides extensive debugging features. These are enabled either by the `--debug' (`-x') command line option to radiusd (see section 4. How to Start the Daemon.), or by the level statement in the debug category (see section logging statement). Both cases require as an argument a valid debug specification.

A debug specification sets the module for which the debugging should be enabled and the debugging level. The higher the level is, the more detailed information is provided. The module name and level are separated by an equal sign. If the level is omitted, the highest possible level (100) is assumed. The module name may be abbreviated to the first N characters, in which case the first matching module is selected. Several such specifications can be specified, in which case they should be separated by commas. For example, the following is a valid debug specification:

proxy.c=10,files.c,config.y=1

It sets debug level 10 for module proxy.c, 100 for files.c, and 1 for config.y.

The modules and debugging levels are subject to change from release to release.

10.3 Test Mode

Test mode is used to test various aspects of radius configuration, without starting the daemon. To enter test mode, run

radiusd -mt

You will see usual radiusd diagnostics and the following two lines:

** TEST SHELL ** (radiusd) _

The string `** TEST SHELL **' indicates that radiusd has entered test mode, the string `(radiusd)' is the shell prompt, indicating that radiusd is waiting for your commands.

The syntax of test shell command resembles that of Bourne shell: each command consists of a list of words separated by any amount of whitespace. Each word is either a sequence of allowed word characters (i.e. alphabetical characters, decimal digits, dashes and underscores), or any sequence of characters enclosed in a pair of double quotes. The very first word is a command verb, the rest of words are arguments to this command verb. A command verb may be used in its full form, in its abbreviated form (i.e. you may type only several first characters of the verb, the only condition being that they do not coincide with another command verb), or in it's short form.

The first command you should know is help (or, in its short form, h). This command takes no arguments and displays the short summary of all the available commands. Here is an example of its output:

(radiusd) help h help Print this help screen q query-nas NAS LOGIN SID PORT [IP] Query the given NAS g guile Enter Guile rs rewrite-stack [NUMBER] Print or set the Rewrite stack size r run-rewrite FUNCTION(args..) Run given Rewrite function s source FILE Source the given Rewrite file t timespan TIMESPAN [DOW [HH [MM]]] Check the timespan interval d debug LEVEL Set debugging level rd request-define [PAIR [,PAIR]] Define a request rp request-print Print the request quit quit Quit the shell

Each line of the output consists of three fields. The first field shows the short command form. The second one lists its full form and its arguments, optional arguments being enclosed in square brackets. The third field contains short textual description of the command.

Test Shell Command: query-nas nas login sid port [ip]

Test Shell Abbreviation: q

Queries the given NAS about the session described by its arguments. This command is useful in testing simultaneous login verification (see section 7.9 Multiple Login Checking. Its arguments are

nas

Specifies the NAS to query. It cn be its short name as defined in `raddb/naslist', or its fully qualified domain name, or its IP address.

login

Name of the user whose session should be verified.

sid

Session ID.

port

Port number on the NAS.

ip

Framed IP address, assigned to the user.

The command displays the following result codes:

0

The session is not active.

1

The session is active

-1

Some error occurred.

Test Shell Command: guile

Test Shell Abbreviation: g

Enter Guile shell. The command is only available if the package has been compiled with Guile support. For more information, See section 11.3 Guile.

Test Shell Command: rewrite-stack [number]

Test Shell Abbreviation: rs

Prints or sets the Rewrite stack size.

Test Shell Command: run-rewrite function(args ...)

Test Shell Abbreviation: r

Runs given Rewrite function and displays its return value. Function arguments are specified in the usual way, i.e. as a comma-separated list of Rewrite tokens.

If the function being tested operates on request contents (see section 11.2.4 Rewriting Incoming Requests), you may supply the request using request-define command (see below).

Test Shell Command: source file

Test Shell Abbreviation: s

Reads and compiles ("source") the given Rewrite file. The command prints `0' if the file was compiled successfully. Otherwise, it prints `1' and any relevant diagnostics.

Test Shell Command: timespan timespan [day-of-week [hour [minutes]]]

Test Shell Abbreviation: t

Checks whether the given time falls within the timespan interval. Its first argument, timespan, contains the valid radiusd timespan specification (see section 14.3.14 Login-Time). Rest of arguments define the time. If any of these is omitted, the corresponding value from current local time is used.

day-of-week

Ordinal day of week number, counted from 0. I.e.: Sunday -- 0, Monday -- 1, etc.

hour

Hours counted from 0 to 24.

minutes

Minutes.

The following set of samples illustrates this command:

(radiusd) timespan Wk0900-1800 ctime: Tue Dec 2 16:08:47 2003 inside Wk0900-1800: 6720 seconds left (radiusd) timespan Wk0900-1800 0 ctime: Sun Nov 30 16:09:03 2003 OUTSIDE Wk0900-1800: 60660 seconds to wait (radiusd) timespan Wk0900-1800 0 12 30 ctime: Sun Nov 30 12:30:13 2003 OUTSIDE Wk0900-1800: 73800 seconds to wait (radiusd) timespan Wk0900-1800 1 05 00 ctime: Mon Dec 1 05:00:33 2003 OUTSIDE Wk0900-1800: 14400 seconds to wait (radiusd) timespan Wk0900-1800 1 09 10 ctime: Wed Jan 7 22:09:41 2004 OUTSIDE Wk0900-1800: 39060 seconds to wait (radiusd) timespan Wk0900-1800 1 09 10 ctime: Mon Dec 1 09:10:44 2003 inside Wk0900-1800: 31800 seconds left (radiusd)

Test Shell Command: debug level

Test Shell Abbreviation: d

Set debugging level. Level is any valid debug level specification (see section 10.2 Debugging).

Test Shell Command: request-define [pair [,pair]]

Test Shell Abbreviation: rd

Define a request for testing Rewrite functions. The optional arguments are a comma-separated list of A/V pairs. If they are omitted, the command enters interactive mode, allowing you to enter the desired A/V pairs, as in the following example:

(radiusd) request-define Enter the pair list. End with end of file [radiusd] User-Name = smith, User-Password = guessme [radiusd] NAS-IP-Address = 10.10.10.1 [radiusd] NAS-Port-Id = 34 [radiusd] (radiusd)

Notice that any number of A/V pairs may be specified in a line. To finish entering the request, either type an EOF character or enter an empty line.

Test Shell Command: request-print

Test Shell Abbreviation: rp

Prints the request, defined by request-define.

(radiusd) request-print User-Name = (STRING) smith User-Password = (STRING) guessme NAS-IP-Address = (IPADDR) 10.10.10.1 NAS-Port-Id = (INTEGER) 34 (radiusd)

Test Shell Command: quit

Immediately quits the shell.