[Help-gnu-radius] No user name at acct start

[Kurt Tragant]

Hello list,

I get a request from another radius (not under my control) to my radius.
User is address@hidden Strip-Names is on. The user is granted access
by my radius. But then the acct start record is written without the user
name. In the acct stop record the user name (test) is included, but I get an
error, because the acct start record was written without user name. Is there
a mistake on my side or doesn't send the NAS (not under my control) the user
name in the acct start record?

Thank you in advance.

Best regards
Kurt

users:
------

test    Auth-Type = Local,
        Password = password
        Service-Type = Login-User

config:
-------

[snip]
auth {
        listen a.b.c.d;
        max-requests 127;
        request-cleanup-delay 2;
        detail yes;
        detail-file-name "=nas_name(request_source_ip()) +
\"/detail.auth\"";
        strip-names yes;
        checkrad-assume-logged yes;
};

acct {
        listen a.b.c.d;
        max-requests 127;
        request-cleanup-delay 2;
        detail-file-name "=nas_name(request_source_ip()) + \"/detail\"";
};
[snip]

realms:
-------

testdomain.com  LOCAL

detail:
-------

Wed Mar  8 13:24:39 2006
        Acct-Status-Type = Start
        Acct-Session-Id = 1234
        Timestamp = 1141820679
        Request-Authenticator = Verified

Wed Mar  8 13:24:46 2006
        Acct-Status-Type = Stop
        Acct-Session-Id = 1234
        User-Name = test
        Acct-Input-Octets = 0
        Acct-Output-Gigawords = 0
        Acct-Output-Octets = 5061119
        Acct-Input-Gigawords = 0
        Acct-Session-Time = 9
        Framed-IP-Address = e.f.g.h
        Acct-Output-Packets = 0
        Acct-Link-Count = 0
        Timestamp = 1141820686
        Request-Authenticator = Verified

detail.auth:
------------

Wed Mar  8 13:24:39 2006
        User-Name = address@hidden
        Timestamp = 1141820679
        Request-Authenticator = None

debug information:
------------------

Mär 08 13:24:39 Main.debug: input.c:251:input_select: select returned 1
Mär 08 13:24:39 Main.debug: input.c:136:channel_handle: handling method udp
Mär 08 13:24:39 Auth.debug: files.c:943:client_lookup_ip: Found secret for
w.x.y.z/255.255.255.255 (w.x.y.z): secret
Mär 08 13:24:39 Auth.debug: request.c:392:request_handle: AUTH request 0
added to the list. 1 requests held.
Mär 08 13:24:39 Auth.debug: rpp.c:562:rpp_forward_request: sending request
to 15642
Mär 08 13:24:39 Auth.debug: rpp.c:221:rpp_fd_write: size=28
Mär 08 13:24:39 Auth.debug: rpp.c:121:pipe_write: n = 4
Mär 08 13:24:39 Auth.debug: rpp.c:200:rpp_fd_read: nbytes=28
Mär 08 13:24:39 Auth.debug: rpp.c:121:pipe_write: n = 28
Mär 08 13:24:39 Auth.debug: rpp.c:212:rpp_fd_read: return 28
Mär 08 13:24:39 Auth.debug: rpp.c:226:rpp_fd_write: return 28
Mär 08 13:24:39 Auth.debug: rpp.c:221:rpp_fd_write: size=62
Mär 08 13:24:39 Auth.debug: rpp.c:121:pipe_write: n = 4
Mär 08 13:24:39 Auth.debug: rpp.c:200:rpp_fd_read: nbytes=62
Mär 08 13:24:39 Auth.debug: rpp.c:121:pipe_write: n = 62
Mär 08 13:24:39 Auth.debug: rpp.c:212:rpp_fd_read: return 62
Mär 08 13:24:39 Auth.debug: rpp.c:226:rpp_fd_write: return 62
Mär 08 13:24:39 Auth.debug: input.c:258:input_select: exit
Mär 08 13:24:39 Auth.debug: files.c:943:client_lookup_ip: Found secret for
w.x.y.z/255.255.255.255 (w.x.y.z): secret
Mär 08 13:24:39 Main.debug: input.c:224:input_select: enter
Mär 08 13:24:39 Auth.debug: request.c:392:request_handle: AUTH request 0
added to the list. 1 requests held.
Mär 08 13:24:39 Auth.debug: files.c:698:hints_setup: called for
address@hidden'
Mär 08 13:24:39 Auth.debug: files.c:856:huntgroup_access: returning 1
Mär 08 13:24:39 Auth.debug: auth.c:761:rad_authenticate: auth: test
Mär 08 13:24:39 Auth.debug: files.c:324:user_find_sym: looking for test
Mär 08 13:24:39 Auth.debug: sql.c:733:attach_sql_connection: allocating new
0 sql connection
Mär 08 13:24:39 Auth.debug: sql.c:747:attach_sql_connection: connection 0
timed out: reconnect
Mär 08 13:24:39 Auth.debug: sql.c:752:attach_sql_connection: attaching
0x8086d98 [0]
Mär 08 13:24:39 Auth.debug: sql.c:709:sql_cache_lookup: looking up SELECT
attr,value,op FROM attrib WHERE user_name='test' AND op IS NOT NULL
Mär 08 13:24:39 Auth.debug: sql.c:717:sql_cache_lookup: NOT FOUND
Mär 08 13:24:39 Auth.debug: sql.c:664:sql_cache_retrieve: query: SELECT
attr,value,op FROM attrib WHERE user_name='test' AND op IS NOT NULL
Mär 08 13:24:39 Auth.debug: sql.c:645:sql_cache_insert: cache: 0,(0,0)
Mär 08 13:24:39 Auth.debug: sql.c:651:sql_cache_insert: inserting at pos 0
Mär 08 13:24:39 Auth.debug: sql.c:654:sql_cache_insert: tail: 0,1
Mär 08 13:24:39 Auth.debug: files.c:1433:paircmp: returning 0
Mär 08 13:24:39 Auth.debug: sql.c:752:attach_sql_connection: attaching
0x8086d98 [0]
Mär 08 13:24:39 Auth.debug: sql.c:709:sql_cache_lookup: looking up SELECT
attr,value FROM attrib WHERE user_name='test' AND op IS NULL
Mär 08 13:24:39 Auth.debug: sql.c:717:sql_cache_lookup: NOT FOUND
Mär 08 13:24:39 Auth.debug: sql.c:664:sql_cache_retrieve: query: SELECT
attr,value FROM attrib WHERE user_name='test' AND op IS NULL
Mär 08 13:24:39 Auth.debug: sql.c:645:sql_cache_insert: cache: 1,(0,1)
Mär 08 13:24:39 Auth.debug: sql.c:651:sql_cache_insert: inserting at pos 1
Mär 08 13:24:39 Auth.debug: sql.c:654:sql_cache_insert: tail: 0,2
Mär 08 13:24:39 Auth.debug: files.c:337:user_find_sym: returning 1
Mär 08 13:24:39 Auth.debug: auth.c:602:rad_check_password: auth_type=0,
userpass=password, name=test, password=password
Mär 08 13:24:39 Auth.debug: auth.c:648:rad_check_password:   auth: Local
Mär 08 13:24:39 Auth.debug: auth.c:1282:sfn_ack: ACK: test
Mär 08 13:24:39 Auth.notice: (Access-Request HW3 0 "test"): Login OK [test]
Mär 08 13:24:39 Auth.debug: sql.c:764:detach_sql_connection: detaching
0x8086d98 [0]
Mär 08 13:24:39 Auth.debug: sql.c:767:detach_sql_connection: destructing sql
connection 0x8086d98
Mär 08 13:24:39 Auth.debug: rpp.c:688:rpp_request_handler: notifying the
master
Mär 08 13:24:39 Auth.debug: rpp.c:221:rpp_fd_write: size=8
Mär 08 13:24:39 Auth.debug: rpp.c:226:rpp_fd_write: return 8
Mär 08 13:24:39 Main.debug: input.c:251:input_select: select returned 1
Mär 08 13:24:39 Main.debug: input.c:136:channel_handle: handling method rpp
Mär 08 13:24:39 Main.debug: rpp.c:200:rpp_fd_read: nbytes=8
Mär 08 13:24:39 Main.debug: rpp.c:212:rpp_fd_read: return 8
Mär 08 13:24:39 Main.debug: rpp.c:731:rpp_input_handler: updating pid 15642
Mär 08 13:24:39 Main.debug: request.c:406:request_update: enter, pid=15642,
ptr = (nil)
Mär 08 13:24:39 Main.debug: request.c:418:request_update: exit
Mär 08 13:24:39 Main.debug: input.c:258:input_select: exit
Mär 08 13:24:39 Main.debug: input.c:224:input_select: enter
Mär 08 13:24:39 Main.debug: input.c:251:input_select: select returned 1
Mär 08 13:24:39 Main.debug: input.c:136:channel_handle: handling method udp
Mär 08 13:24:39 Acct.debug: files.c:943:client_lookup_ip: Found secret for
w.x.y.z/255.255.255.255 (w.x.y.z): secret
Mär 08 13:24:39 Acct.debug: request.c:392:request_handle: ACCT request 0
added to the list. 2 requests held.
Mär 08 13:24:39 Acct.debug: rpp.c:562:rpp_forward_request: sending request
to 15642
Mär 08 13:24:39 Acct.debug: rpp.c:221:rpp_fd_write: size=28
Mär 08 13:24:39 Acct.debug: rpp.c:121:pipe_write: n = 4
Mär 08 13:24:39 Auth.debug: rpp.c:200:rpp_fd_read: nbytes=28
Mär 08 13:24:39 Acct.debug: rpp.c:121:pipe_write: n = 28
Mär 08 13:24:39 Auth.debug: rpp.c:212:rpp_fd_read: return 28
Mär 08 13:24:39 Acct.debug: rpp.c:226:rpp_fd_write: return 28
Mär 08 13:24:39 Acct.debug: rpp.c:221:rpp_fd_write: size=69
Mär 08 13:24:39 Acct.debug: rpp.c:121:pipe_write: n = 4
Mär 08 13:24:39 Auth.debug: rpp.c:200:rpp_fd_read: nbytes=69
Mär 08 13:24:39 Acct.debug: rpp.c:121:pipe_write: n = 69
Mär 08 13:24:39 Auth.debug: rpp.c:212:rpp_fd_read: return 69
Mär 08 13:24:39 Acct.debug: rpp.c:226:rpp_fd_write: return 69
Mär 08 13:24:39 Acct.debug: files.c:943:client_lookup_ip: Found secret for
w.x.y.z/255.255.255.255 (w.x.y.z): secret
Mär 08 13:24:39 Acct.debug: input.c:258:input_select: exit
Mär 08 13:24:39 Acct.debug: request.c:392:request_handle: ACCT request 0
added to the list. 2 requests held.
Mär 08 13:24:39 Main.debug: input.c:224:input_select: enter
Mär 08 13:24:39 Acct.debug: files.c:698:hints_setup: called for `'
Mär 08 13:24:39 Acct.debug: files.c:856:huntgroup_access: returning 1
Mär 08 13:24:39 Acct.debug: acct.c:332:rad_acct_system: start: User  at NAS
HW3 port 0 session 1234
Mär 08 13:24:39 Acct.debug: sql.c:733:attach_sql_connection: allocating new
1 sql connection
Mär 08 13:24:39 Acct.debug: sql.c:747:attach_sql_connection: connection 1
timed out: reconnect
Mär 08 13:24:39 Acct.debug: sql.c:752:attach_sql_connection: attaching
0x80877e8 [1]
Mär 08 13:24:39 Acct.debug: sql.c:764:detach_sql_connection: detaching
0x80877e8 [1]
Mär 08 13:24:39 Acct.debug: sql.c:767:detach_sql_connection: destructing sql
connection 0x80877e8
Mär 08 13:24:39 Acct.debug: rpp.c:688:rpp_request_handler: notifying the
master
Mär 08 13:24:39 Acct.debug: rpp.c:221:rpp_fd_write: size=8
Mär 08 13:24:39 Acct.debug: rpp.c:226:rpp_fd_write: return 8
Mär 08 13:24:39 Main.debug: input.c:251:input_select: select returned 1
Mär 08 13:24:39 Main.debug: input.c:136:channel_handle: handling method rpp
Mär 08 13:24:39 Main.debug: rpp.c:200:rpp_fd_read: nbytes=8
Mär 08 13:24:39 Main.debug: rpp.c:212:rpp_fd_read: return 8
Mär 08 13:24:39 Main.debug: rpp.c:731:rpp_input_handler: updating pid 15642
Mär 08 13:24:39 Main.debug: request.c:406:request_update: enter, pid=15642,
ptr = (nil)
Mär 08 13:24:39 Main.debug: request.c:418:request_update: exit
Mär 08 13:24:39 Main.debug: input.c:258:input_select: exit
Mär 08 13:24:39 Main.debug: input.c:224:input_select: enter
Mär 08 13:24:46 Main.debug: input.c:251:input_select: select returned 1
Mär 08 13:24:46 Main.debug: input.c:136:channel_handle: handling method udp
Mär 08 13:24:46 Acct.debug: files.c:943:client_lookup_ip: Found secret for
w.x.y.z/255.255.255.255 (w.x.y.z): secret
Mär 08 13:24:46 Acct.debug: request.c:202:_request_iterator: deleting
completed AUTH request
Mär 08 13:24:46 Acct.debug: request.c:202:_request_iterator: deleting
completed ACCT request
Mär 08 13:24:46 Acct.debug: request.c:392:request_handle: ACCT request 0
added to the list. 1 requests held.
Mär 08 13:24:46 Acct.debug: rpp.c:562:rpp_forward_request: sending request
to 15642
Mär 08 13:24:46 Acct.debug: rpp.c:221:rpp_fd_write: size=28
Mär 08 13:24:46 Acct.debug: rpp.c:121:pipe_write: n = 4
Mär 08 13:24:46 Acct.debug: rpp.c:200:rpp_fd_read: nbytes=28
Mär 08 13:24:46 Acct.debug: rpp.c:121:pipe_write: n = 28
Mär 08 13:24:46 Acct.debug: rpp.c:212:rpp_fd_read: return 28
Mär 08 13:24:46 Acct.debug: rpp.c:226:rpp_fd_write: return 28
Mär 08 13:24:46 Acct.debug: rpp.c:221:rpp_fd_write: size=127
Mär 08 13:24:46 Acct.debug: rpp.c:121:pipe_write: n = 4
Mär 08 13:24:46 Acct.debug: rpp.c:200:rpp_fd_read: nbytes=127
Mär 08 13:24:46 Acct.debug: rpp.c:121:pipe_write: n = 127
Mär 08 13:24:46 Acct.debug: rpp.c:212:rpp_fd_read: return 127
Mär 08 13:24:46 Acct.debug: rpp.c:226:rpp_fd_write: return 127
Mär 08 13:24:46 Acct.debug: input.c:258:input_select: exit
Mär 08 13:24:46 Acct.debug: files.c:943:client_lookup_ip: Found secret for
w.x.y.z/255.255.255.255 (w.x.y.z): secret
Mär 08 13:24:46 Main.debug: input.c:224:input_select: enter
Mär 08 13:24:46 Acct.debug: request.c:202:_request_iterator: deleting
completed AUTH request
Mär 08 13:24:46 Acct.debug: request.c:202:_request_iterator: deleting
completed ACCT request
Mär 08 13:24:46 Acct.debug: request.c:392:request_handle: ACCT request 0
added to the list. 1 requests held.
Mär 08 13:24:46 Acct.debug: files.c:698:hints_setup: called for `test'
Mär 08 13:24:46 Acct.debug: files.c:856:huntgroup_access: returning 1
Mär 08 13:24:46 Acct.debug: acct.c:332:rad_acct_system: stop: User test at
NAS HW3 port 0 session 1234
Mär 08 13:24:46 Acct.debug: sql.c:733:attach_sql_connection: allocating new
1 sql connection
Mär 08 13:24:46 Acct.debug: sql.c:747:attach_sql_connection: connection 1
timed out: reconnect
Mär 08 13:24:46 Acct.debug: sql.c:752:attach_sql_connection: attaching
0x8087ba0 [1]
Mär 08 13:24:46 Acct.warning: (Accounting-Request HW3 0 "test"):
acct_stop_query updated 0 records
Mär 08 13:24:46 Acct.debug: sql.c:764:detach_sql_connection: detaching
0x8087ba0 [1]
Mär 08 13:24:46 Acct.debug: sql.c:767:detach_sql_connection: destructing sql
connection 0x8087ba0
Mär 08 13:24:46 Acct.debug: rpp.c:688:rpp_request_handler: notifying the
master
Mär 08 13:24:46 Acct.debug: rpp.c:221:rpp_fd_write: size=8
Mär 08 13:24:46 Acct.debug: rpp.c:226:rpp_fd_write: return 8
Mär 08 13:24:46 Main.debug: input.c:251:input_select: select returned 1
Mär 08 13:24:46 Main.debug: input.c:136:channel_handle: handling method rpp
Mär 08 13:24:46 Main.debug: rpp.c:200:rpp_fd_read: nbytes=8
Mär 08 13:24:46 Main.debug: rpp.c:212:rpp_fd_read: return 8
Mär 08 13:24:46 Main.debug: rpp.c:731:rpp_input_handler: updating pid 15642
Mär 08 13:24:46 Main.debug: request.c:406:request_update: enter, pid=15642,
ptr = (nil)
Mär 08 13:24:46 Main.debug: request.c:418:request_update: exit
Mär 08 13:24:46 Main.debug: input.c:258:input_select: exit
Mär 08 13:24:46 Main.debug: input.c:224:input_select: enter

-- 
"Feel free" mit GMX FreeMail!
Monat für Monat 10 FreeSMS inklusive! http://www.gmx.net