Hello,
I'm looking for some pointers in troubleshooting a radius accounting issue.
We're running a new installation of PF 9.0.1. CentOS 7. However, this is
not my first time deploying the solution.
The issue: nodes are displaying an "unknown" status within the UI.
The packetfence server is definitely receiving accounting messages. I have
no reason to doubt the switch configuration (I could elaborate but didn't
want to write a novel). I've confirmed that these messages are being
received through tcpdump and raddebug. In reviewing the output of raddebug,
it's confirmed that they're being received and processed.
Sent Access-Accept Id 18 from 127.0.0.1:18122 to 127.0.0.1:33385 length 0
(4495) Wed Jun 5 10:03:00 2019: Debug: FreeRADIUS-Total-Access-Requests
= 4467
(4495) Wed Jun 5 10:03:00 2019: Debug: FreeRADIUS-Total-Access-Accepts =
0
(4495) Wed Jun 5 10:03:00 2019: Debug: FreeRADIUS-Total-Access-Rejects =
0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Access-Challenges = 0
(4495) Wed Jun 5 10:03:00 2019: Debug: FreeRADIUS-Total-Auth-Responses =
0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Auth-Duplicate-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Auth-Malformed-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Auth-Invalid-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Auth-Dropped-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Auth-Unknown-Types = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Accounting-Requests = 29
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Accounting-Responses = 29
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Acct-Duplicate-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Acct-Malformed-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Acct-Invalid-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Acct-Dropped-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Acct-Unknown-Types = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Accepts = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Rejects = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Access-Challenges = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Responses = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Duplicate-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Malformed-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Invalid-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Dropped-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Auth-Unknown-Types = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Accounting-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Accounting-Responses = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Duplicate-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Malformed-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Invalid-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Dropped-Requests = 0
(4495) Wed Jun 5 10:03:00 2019: Debug:
FreeRADIUS-Total-Proxy-Acct-Unknown-Types = 0
(4495) Wed Jun 5 10:03:00 2019: Debug: Finished request
(4495) Wed Jun 5 10:03:05 2019: Debug: Cleaning up request packet ID 18
with timestamp +67052
I don't see any errors in the raddebug output. Oddly, when it goes to
perform an update (this is an accounting 'Acct-Status-Type = Stop'
message), no update is performed on the query:
(4491) Wed Jun 5 10:02:26 2019: Debug: sql: SQL query returned: success
(4491) Wed Jun 5 10:02:26 2019: Debug: sql: 0 record(s) updated
(4491) Wed Jun 5 10:02:26 2019: Debug: sql: No additional queries
configured
Also, the API call seems to complete without error.
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: Processing response header
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: Status : 100 (Continue)
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: Continuing...
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: Processing response header
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: Status : 200 (OK)
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: Type : json
(application/json)
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: Parsing attribute
"control:PacketFence-Authorization-Status"
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: EXPAND allow
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: --> allow
(4491) Wed Jun 5 10:02:26 2019: Debug: rest:
PacketFence-Authorization-Status := "allow"
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: Parsing attribute
"Reply-Message"
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: EXPAND Accounting ok
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: --> Accounting ok
(4491) Wed Jun 5 10:02:26 2019: Debug: rest: Reply-Message := "Accounting
ok"
However, in the database.... the locationlog table is full of entries with
no end time. Could this be related? I'm not sure where to go from here.
I've built a 2nd server and am trying to reproduce the issue but have so
far been unsuccessful.
Here's an example:
MariaDB [pf]> select * from locationlog where mac="08:00:0f:8c:3e:17";
+-----+-----------+-------------------+--------------+-------+------+--------------+-----------------+---------------------+----------------+------+---------------------+---------------------+--------------+-------------------+--------------------+-------+------------+-----------------------+------+
| id | tenant_id | mac | switch | port | vlan | role
| connection_type | connection_sub_type | dot1x_username | ssid |
start_time | end_time | switch_ip | switch_mac
| stripped_user_name | realm | session_id | ifDesc | voip |
+-----+-----------+-------------------+--------------+-------+------+--------------+-----------------+---------------------+----------------+------+---------------------+---------------------+--------------+-------------------+--------------------+-------+------------+-----------------------+------+
| 141 | 1 | 08:00:0f:8c:3e:17 | 172.19.23.12 | 10113 | 1922 | voice
| Ethernet-NoEAP | NULL | 08000f8c3e17 | |
2019-06-05 14:34:52 | 0000-00-00 00:00:00 | 172.19.23.12 |
7c:69:f6:7b:8c:0d | NULL | NULL | NULL |
GigabitEthernet1/0/13 | no |
| 142 | 1 | 08:00:0f:8c:3e:17 | 172.19.23.12 | 10113 | 1922 | voice
| Ethernet-NoEAP | NULL | 08000f8c3e17 | |
2019-06-05 14:35:57 | 0000-00-00 00:00:00 | 172.19.23.12 |
7c:69:f6:7b:8c:0d | NULL | NULL | NULL |
GigabitEthernet1/0/13 | no |
| 143 | 1 | 08:00:0f:8c:3e:17 | 172.19.23.12 | 10113 | 1922 | voice
| Ethernet-NoEAP | NULL | 08000f8c3e17 | |
2019-06-05 14:53:09 | 0000-00-00 00:00:00 | 172.19.23.12 |
7c:69:f6:7b:8c:0d | NULL | NULL | NULL |
GigabitEthernet1/0/13 | no |
| 140 | 1 | 08:00:0f:8c:3e:17 | 172.19.23.12 | 10113 | 1928 |
registration | Ethernet-NoEAP | NULL | 08000f8c3e17 |
| 2019-06-05 14:23:30 | 2019-06-05 14:34:52 | 172.19.23.12 |
7c:69:f6:7b:8c:0d | 08000f8c3e17 | null | NULL |
GigabitEthernet1/0/13 | no |
+-----+-----------+-------------------+--------------+-------+------+--------------+-----------------+---------------------+----------------+------+---------------------+---------------------+--------------+-------------------+--------------------+-------+------------+-----------------------+------+
4 rows in set (0.00 sec)
Thanks in advance!
*Nick Pier*
_______________________________________________
PacketFence-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/packetfence-users
