accounting data
Periko Support
pheriko.support at gmail.com
Sun Nov 11 04:36:49 CET 2012
On Sat, Nov 10, 2012 at 6:27 AM, Alan DeKok <aland at deployingradius.com> wrote:
> Periko Support wrote:
>> This works, but I would like to understand, I can try that steps a
>> lot times and every time it give me the same result: 1770, doesn't
>> suppose that every time I run the same steps the counter must be
>> lower?
>
> Only if the NAS is sending accounting packets.
>
> What does the debug output say?
>
> Alan DeKok.
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
This is the output:
radtest alice test 127.0.0.1 100 testing123
Sending Access-Request of id 32 to 127.0.0.1 port 1812
User-Name = "alice"
User-Password = "test"
NAS-IP-Address = 127.0.0.1
NAS-Port = 100
Message-Authenticator = 0x00000000000000000000000000000000
rad_recv: Access-Accept packet from host 127.0.0.1 port 1812, id=32, length=40
Reply-Message = "Hello, alice"
Session-Timeout = 300
debug:
rad_recv: Access-Request packet from host 127.0.0.1 port 36311, id=32, length=75
User-Name = "alice"
User-Password = "test"
NAS-IP-Address = 127.0.0.1
NAS-Port = 100
Message-Authenticator = 0x2c214bd6f2cb15d2c0d224a851ca167d
# Executing section authorize from file /etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[suffix] No '@' in User-Name = "alice", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] No EAP-Message, not doing EAP
++[eap] returns noop
[files] users: Matched entry alice at line 170
[files] expand: Hello, %{User-Name} -> Hello, alice
++[files] returns ok
rlm_counter: Entering module authorize code
rlm_counter: Searching the database for key 'alice'
rlm_counter: Could not find the requested key in the database.
rlm_counter: Check item = 300, Count = 0
rlm_counter: res is greater than zero
rlm_counter: (Check item - counter) is greater than zero
rlm_counter: Authorized user alice, check_item=300, counter=0
rlm_counter: Sent Reply-Item for user alice, Type=Session-Timeout, value=300
++[daily] returns ok
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns updated
Found Auth-Type = PAP
# Executing group from file /etc/raddb/sites-enabled/default
+- entering group PAP {...}
[pap] login attempt with password "test"
[pap] Using clear text password "test"
[pap] User authenticated successfully
++[pap] returns ok
# Executing section post-auth from file /etc/raddb/sites-enabled/default
+- entering group post-auth {...}
++[exec] returns noop
Sending Access-Accept of id 32 to 127.0.0.1 port 36311
Reply-Message = "Hello, alice"
Session-Timeout = 300
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
Cleaning up request 0 ID 32 with timestamp +42
Ready to process requests.
accouting start:
radclient 127.0.0.1 auto testing123 -f 4088_06_acct_start.txt
Received response ID 15, code 5, length = 20
debug:
rad_recv: Accounting-Request packet from host 127.0.0.1 port 48415,
id=15, length=144
Acct-Session-Id = "4D2BB8AC-00000098"
Acct-Status-Type = Start
Acct-Authentic = RADIUS
User-Name = "alice"
NAS-Port = 0
Called-Station-Id = "00-02-6F-AA-AA-AA:My Wireless"
Calling-Station-Id = "00-1C-B3-AA-AA-AA"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 48Mbps 802.11b"
# Executing section preacct from file /etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 0,Client-IP-Address =
127.0.0.1,NAS-IP-Address = 127.0.0.1,Acct-Session-Id =
"4D2BB8AC-00000098",User-Name = "alice"'
[acct_unique] Acct-Unique-Session-ID = "e38661b89c4e83d0".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "alice", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail] expand: %{Packet-Src-IP-Address} -> 127.0.0.1
[detail] expand:
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
-> /var/log/radius/radacct/127.0.0.1/detail-20121110
[detail] /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/radius/radacct/127.0.0.1/detail-20121110
[detail] expand: %t -> Sat Nov 10 19:35:50 2012
++[detail] returns ok
rlm_counter: We only run on Accounting-Stop packets.
++[daily] returns noop
++[unix] returns ok
[radutmp] expand: /var/log/radius/radutmp -> /var/log/radius/radutmp
[radutmp] expand: %{User-Name} -> alice
++[radutmp] returns ok
++[exec] returns noop
[attr_filter.accounting_response] expand: %{User-Name} -> alice
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 15 to 127.0.0.1 port 48415
Finished request 1.
Cleaning up request 1 ID 15 with timestamp +176
Going to the next request
Ready to process requests.
accouting stop:
radclient 127.0.0.1 auto testing123 -f 4088_06_acct_stop.txt
Received response ID 69, code 5, length = 20
debug:
rad_recv: Accounting-Request packet from host 127.0.0.1 port 37075,
id=69, length=180
Acct-Session-Id = "4D2BB8AC-00000098"
Acct-Status-Type = Stop
Acct-Authentic = RADIUS
User-Name = "alice"
NAS-Port = 0
Called-Station-Id = "00-02-6F-AA-AA-AA:My Wireless"
Calling-Station-Id = "00-1C-B3-AA-AA-AA"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 48Mbps 802.11b"
Acct-Session-Time = 180
Acct-Input-Packets = 25
Acct-Output-Packets = 7
Acct-Input-Octets = 3407
Acct-Output-Octets = 867
Acct-Terminate-Cause = User-Request
# Executing section preacct from file /etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 0,Client-IP-Address =
127.0.0.1,NAS-IP-Address = 127.0.0.1,Acct-Session-Id =
"4D2BB8AC-00000098",User-Name = "alice"'
[acct_unique] Acct-Unique-Session-ID = "e38661b89c4e83d0".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "alice", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail] expand: %{Packet-Src-IP-Address} -> 127.0.0.1
[detail] expand:
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
-> /var/log/radius/radacct/127.0.0.1/detail-20121110
[detail] /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/radius/radacct/127.0.0.1/detail-20121110
[detail] expand: %t -> Sat Nov 10 19:37:05 2012
++[detail] returns ok
rlm_counter: Packet Unique ID = 'e38661b89c4e83d0'
rlm_counter: Searching the database for key 'alice'
rlm_counter: Could not find the requested key in the database.
rlm_counter: User=alice, New Counter=180.
rlm_counter: Storing new value in database.
rlm_counter: New value stored successfully.
++[daily] returns ok
++[unix] returns ok
[radutmp] expand: /var/log/radius/radutmp -> /var/log/radius/radutmp
[radutmp] expand: %{User-Name} -> alice
++[radutmp] returns ok
++[exec] returns noop
[attr_filter.accounting_response] expand: %{User-Name} -> alice
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 69 to 127.0.0.1 port 37075
Finished request 2.
Cleaning up request 2 ID 69 with timestamp +251
Going to the next request
Ready to process requests.
Last step authenticated the same user:
radtest alice test 127.0.0.1 100 testing123
Sending Access-Request of id 151 to 127.0.0.1 port 1812
User-Name = "alice"
User-Password = "test"
NAS-IP-Address = 127.0.0.1
NAS-Port = 100
Message-Authenticator = 0x00000000000000000000000000000000
rad_recv: Access-Accept packet from host 127.0.0.1 port 1812, id=151, length=40
Reply-Message = "Hello, alice"
Session-Timeout = 120
debug:
rad_recv: Access-Request packet from host 127.0.0.1 port 53539,
id=151, length=75
User-Name = "alice"
User-Password = "test"
NAS-IP-Address = 127.0.0.1
NAS-Port = 100
Message-Authenticator = 0xf1558260006fc896f92ffc325c8ea850
# Executing section authorize from file /etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[suffix] No '@' in User-Name = "alice", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] No EAP-Message, not doing EAP
++[eap] returns noop
[files] users: Matched entry alice at line 170
[files] expand: Hello, %{User-Name} -> Hello, alice
++[files] returns ok
rlm_counter: Entering module authorize code
rlm_counter: Searching the database for key 'alice'
rlm_counter: Key Found.
rlm_counter: Check item = 300, Count = 180
rlm_counter: res is greater than zero
rlm_counter: (Check item - counter) is greater than zero
rlm_counter: Authorized user alice, check_item=300, counter=180
rlm_counter: Sent Reply-Item for user alice, Type=Session-Timeout, value=120
++[daily] returns ok
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns updated
Found Auth-Type = PAP
# Executing group from file /etc/raddb/sites-enabled/default
+- entering group PAP {...}
[pap] login attempt with password "test"
[pap] Using clear text password "test"
[pap] User authenticated successfully
++[pap] returns ok
# Executing section post-auth from file /etc/raddb/sites-enabled/default
+- entering group post-auth {...}
++[exec] returns noop
Sending Access-Accept of id 151 to 127.0.0.1 port 53539
Reply-Message = "Hello, alice"
Session-Timeout = 120
Finished request 3.
Going to the next request
Waking up in 4.9 seconds.
Cleaning up request 3 ID 151 with timestamp +315
Ready to process requests.
send a accounting start again:
radclient 127.0.0.1 auto testing123 -f 4088_06_acct_start.txt
Received response ID 5, code 5, length = 20
Here I have wait long time to see the effect, maybe the session has
ended, let see.
Debug:
rad_recv: Accounting-Request packet from host 127.0.0.1 port 43262,
id=5, length=144
Acct-Session-Id = "4D2BB8AC-00000098"
Acct-Status-Type = Start
Acct-Authentic = RADIUS
User-Name = "alice"
NAS-Port = 0
Called-Station-Id = "00-02-6F-AA-AA-AA:My Wireless"
Calling-Station-Id = "00-1C-B3-AA-AA-AA"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 48Mbps 802.11b"
# Executing section preacct from file /etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 0,Client-IP-Address =
127.0.0.1,NAS-IP-Address = 127.0.0.1,Acct-Session-Id =
"4D2BB8AC-00000098",User-Name = "alice"'
[acct_unique] Acct-Unique-Session-ID = "e38661b89c4e83d0".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "alice", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail] expand: %{Packet-Src-IP-Address} -> 127.0.0.1
[detail] expand:
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
-> /var/log/radius/radacct/127.0.0.1/detail-20121110
[detail] /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/radius/radacct/127.0.0.1/detail-20121110
[detail] expand: %t -> Sat Nov 10 19:39:19 2012
++[detail] returns ok
rlm_counter: We only run on Accounting-Stop packets.
++[daily] returns noop
++[unix] returns ok
[radutmp] expand: /var/log/radius/radutmp -> /var/log/radius/radutmp
[radutmp] expand: %{User-Name} -> alice
++[radutmp] returns ok
++[exec] returns noop
[attr_filter.accounting_response] expand: %{User-Name} -> alice
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 5 to 127.0.0.1 port 43262
Finished request 4.
Cleaning up request 4 ID 5 with timestamp +385
Going to the next request
Ready to process requests.
Nos a accounting stop:
radclient 127.0.0.1 auto testing123 -f 4088_06_acct_stop.txt
Received response ID 22, code 5, length = 20
Debug:
rad_recv: Accounting-Request packet from host 127.0.0.1 port 53747,
id=22, length=180
Acct-Session-Id = "4D2BB8AC-00000098"
Acct-Status-Type = Stop
Acct-Authentic = RADIUS
User-Name = "alice"
NAS-Port = 0
Called-Station-Id = "00-02-6F-AA-AA-AA:My Wireless"
Calling-Station-Id = "00-1C-B3-AA-AA-AA"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 48Mbps 802.11b"
Acct-Session-Time = 180
Acct-Input-Packets = 25
Acct-Output-Packets = 7
Acct-Input-Octets = 3407
Acct-Output-Octets = 867
Acct-Terminate-Cause = User-Request
# Executing section preacct from file /etc/raddb/sites-enabled/default
+- entering group preacct {...}
++[preprocess] returns ok
[acct_unique] Hashing 'NAS-Port = 0,Client-IP-Address =
127.0.0.1,NAS-IP-Address = 127.0.0.1,Acct-Session-Id =
"4D2BB8AC-00000098",User-Name = "alice"'
[acct_unique] Acct-Unique-Session-ID = "e38661b89c4e83d0".
++[acct_unique] returns ok
[suffix] No '@' in User-Name = "alice", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
++[files] returns noop
# Executing section accounting from file /etc/raddb/sites-enabled/default
+- entering group accounting {...}
[detail] expand: %{Packet-Src-IP-Address} -> 127.0.0.1
[detail] expand:
/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
-> /var/log/radius/radacct/127.0.0.1/detail-20121110
[detail] /var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d
expands to /var/log/radius/radacct/127.0.0.1/detail-20121110
[detail] expand: %t -> Sat Nov 10 19:41:41 2012
++[detail] returns ok
rlm_counter: Packet Unique ID = 'e38661b89c4e83d0'
rlm_counter: Searching the database for key 'alice'
rlm_counter: Key found.
rlm_counter: Counter Unique ID = 'e38661b89c4e83d0'
rlm_counter: Unique IDs for user match. Droping the request.
++[daily] returns noop
++[unix] returns ok
[radutmp] expand: /var/log/radius/radutmp -> /var/log/radius/radutmp
[radutmp] expand: %{User-Name} -> alice
++[radutmp] returns ok
++[exec] returns noop
[attr_filter.accounting_response] expand: %{User-Name} -> alice
attr_filter: Matched entry DEFAULT at line 12
++[attr_filter.accounting_response] returns updated
Sending Accounting-Response of id 22 to 127.0.0.1 port 53747
Finished request 5.
Cleaning up request 5 ID 22 with timestamp +527
Going to the next request
Ready to process requests.
Now authenticate again:
radtest alice test 127.0.0.1 100 testing123
Sending Access-Request of id 185 to 127.0.0.1 port 1812
User-Name = "alice"
User-Password = "test"
NAS-IP-Address = 127.0.0.1
NAS-Port = 100
Message-Authenticator = 0x00000000000000000000000000000000
rad_recv: Access-Accept packet from host 127.0.0.1 port 1812, id=185, length=40
Reply-Message = "Hello, alice"
Session-Timeout = 120
U see here, again "Session-Timeout=120" didn't change, this is correct?
Debug:
rad_recv: Access-Request packet from host 127.0.0.1 port 43137,
id=185, length=75
User-Name = "alice"
User-Password = "test"
NAS-IP-Address = 127.0.0.1
NAS-Port = 100
Message-Authenticator = 0xb5383068f133c6976f9257aad3c400b4
# Executing section authorize from file /etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[suffix] No '@' in User-Name = "alice", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[eap] No EAP-Message, not doing EAP
++[eap] returns noop
[files] users: Matched entry alice at line 170
[files] expand: Hello, %{User-Name} -> Hello, alice
++[files] returns ok
rlm_counter: Entering module authorize code
rlm_counter: Searching the database for key 'alice'
rlm_counter: Key Found.
rlm_counter: Check item = 300, Count = 180
rlm_counter: res is greater than zero
rlm_counter: (Check item - counter) is greater than zero
rlm_counter: Authorized user alice, check_item=300, counter=180
rlm_counter: Sent Reply-Item for user alice, Type=Session-Timeout, value=120
++[daily] returns ok
++[expiration] returns noop
++[logintime] returns noop
++[pap] returns updated
Found Auth-Type = PAP
# Executing group from file /etc/raddb/sites-enabled/default
+- entering group PAP {...}
[pap] login attempt with password "test"
[pap] Using clear text password "test"
[pap] User authenticated successfully
++[pap] returns ok
# Executing section post-auth from file /etc/raddb/sites-enabled/default
+- entering group post-auth {...}
++[exec] returns noop
Sending Access-Accept of id 185 to 127.0.0.1 port 43137
Reply-Message = "Hello, alice"
Session-Timeout = 120
Finished request 6.
Going to the next request
Waking up in 4.9 seconds.
Cleaning up request 6 ID 185 with timestamp +566
Ready to process requests.
The counter is good or is some wrong, the Session-Timeout must be less
than 120 or everything is correct?
I would like to understand this part, thanks!!!
More information about the Freeradius-Users
mailing list