On Sat, Nov 10, 2012 at 6:27 AM, Alan DeKok <aland@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!!!