Audit log empty after upgrading to 13.0

[cmammoli]

Describe the bug After upgrading to PF13.0 I noticed that the radius auditing section is not recording any entry

To Reproduce Steps to reproduce the behavior:

1. Upgrade to PF13
2. Perform a bunch of 802.1x/portal authentications
3. Go to "auditing"
4. No records are present

Expected behavior Radius audit logs should be visible

Additional context In /usr/local/pf/logs/pfcron.log I see

[root@srvpf ~]# grep flush_radius_audit_log /usr/local/pf/logs/pfcron.log

Oct  9 16:55:21 srvpf pfcron-docker-wrapper[3694]: t=2023-10-09T16:55:21+0200 lvl=info msg="task 'flush_radius_audit_log' created with id 18 with schedule of @every 1m" pid=7
Oct  9 16:56:21 srvpf pfcron-docker-wrapper[3694]: t=2023-10-09T16:56:21+0200 lvl=info msg="Running flush_radius_audit_log" pid=7
Oct  9 16:56:21 srvpf pfcron-docker-wrapper[3694]: t=2023-10-09T16:56:21+0200 lvl=eror msg="Job flush_radius_audit_log panic: runtime error: index out of range [1] with length 0" pid=7
Oct  9 16:57:21 srvpf pfcron-docker-wrapper[3694]: t=2023-10-09T16:57:21+0200 lvl=info msg=" Skipped flush_radius_audit_log" pid=7
Oct  9 16:58:21 srvpf pfcron-docker-wrapper[3694]: t=2023-10-09T16:58:21+0200 lvl=info msg=" Skipped flush_radius_audit_log" pid=7
Oct  9 16:59:21 srvpf pfcron-docker-wrapper[3694]: t=2023-10-09T16:59:21+0200 lvl=info msg=" Skipped flush_radius_audit_log" pid=7
Oct  9 17:00:21 srvpf pfcron-docker-wrapper[3694]: t=2023-10-09T17:00:21+0200 lvl=info msg=" Skipped flush_radius_audit_log" pid=7
Oct  9 17:01:21 srvpf pfcron-docker-wrapper[3694]: t=2023-10-09T17:01:21+0200 lvl=info msg=" Skipped flush_radius_audit_log" pid=7
Oct  9 17:02:21 srvpf pfcron-docker-wrapper[3694]: t=2023-10-09T17:02:21+0200 lvl=info msg=" Skipped flush_radius_audit_log" pid=7
Oct  9 17:03:21 srvpf pfcron-docker-wrapper[3694]: t=2023-10-09T17:03:21+0200 lvl=info msg=" Skipped flush_radius_audit_log" pid=7

If I try to run "/usr/local/pf/bin/pfcmd pfcron flush_radius_audit_log" manually I get the same error:

[root@srvpf ~]# /usr/local/pf/bin/pfcmd pfcron flush_radius_audit_log
panic: runtime error: index out of range [1] with length 0

goroutine 1 [running]:
github.com/inverse-inc/packetfence/go/cron.(*FlushRadiusAuditLogJob).argsFromEntry(0xc0002440a0?, {0x0, 0x0, 0xc000244050?})
        /root/rpmbuild/centos-8/BUILD/packetfence-13.0.0/go/cron/flush_radius_audit_log_job.go:167 +0x1058
github.com/inverse-inc/packetfence/go/cron.(*FlushRadiusAuditLogJob).buildQuery(0xc0000c5b38?, {0xc00023a000, 0x64, 0x0?})
        /root/rpmbuild/centos-8/BUILD/packetfence-13.0.0/go/cron/flush_radius_audit_log_job.go:158 +0x1e5
github.com/inverse-inc/packetfence/go/cron.(*FlushRadiusAuditLogJob).flushLogs(0xc00023c000?, {0xc00023a000?, 0x6000?, 0x6feaa0?})
        /root/rpmbuild/centos-8/BUILD/packetfence-13.0.0/go/cron/flush_radius_audit_log_job.go:75 +0x3f
github.com/inverse-inc/packetfence/go/cron.(*FlushRadiusAuditLogJob).Run(0xc0001b6150)
        /root/rpmbuild/centos-8/BUILD/packetfence-13.0.0/go/cron/flush_radius_audit_log_job.go:63 +0x22f
main.runJobNow({0x7ffcc9f475bd, 0x16}, 0x5f82b0a108?)
        /root/rpmbuild/centos-8/BUILD/packetfence-13.0.0/go/cmd/pfcron/main.go:108 +0x304
main.main()
        /root/rpmbuild/centos-8/BUILD/packetfence-13.0.0/go/cmd/pfcron/main.go:153 +0x1c5

In another bug report I found the command "redis-cli --raw LRANGE RADIUS_AUDIT_LOG 0 -1", if I run it I can see all of the missing radius logs

[jrouzierinverse]

Could you send the output of the following command. redis-cli --raw LRANGE RADIUS_AUDIT_LOG 0 -1"

[jrouzierinverse]

Is this on Debian or RHEL?

[cmammoli]

This is EL8 (Rocky) [root@srvpf ~]# cat /etc/redhat-release Rocky Linux release 8.8 (Green Obsidian)

The output of redis-cli is actually 31MB and contains lots of personal informations, can I send it off list?

Regards

[BiasF]

Same problem here. If I can support the troubleshooting with logs, feel free to contact me here or in mantis ticket 0009741

We have a DEBIAN 3-Node cluster (but only one node is currently upgraded to V13)

[cmammoli]

The only strange thing I see in the redis-cli output is that failed authentications by mschap contains lots of strange unescaped newlines:

["Reject",{"PacketFence-KeyBalanced":"f5d1086e7a7df8625ff84c76be7ec5fc","MS-CHAP-Challenge":"0x49c56cdf3e45d1b06467492d70d274c1","MS-CHAP2-Response":"0x082e14a4dbcd17ff00dcc08b0178ca2c64e00000000000000000273479fc3303583e06de83f236e2bb0d5675f64d2ba0e8da","Realm":"null","EAP-Type":"MSCHAPv2","PacketFence-Outer-User":"g.malatesta","Called-Station-SSID":"apra","PacketFence-NTLMv2-Only":"","Stripped-User-Name":"g.malatesta","Cisco-AVPair":["audit-session-id=4810a8c000000eb4d9f22c65","mDNS=true"],"MS-CHAP-User-Name":"g.malatesta","EAP-Message":"0x020800461a020800413114a4dbcd17ff00dcc08b0178ca2c64e00000000000000000273479fc3303583e06de83f236e2bb0d5675f64d2ba0e8da00672e6d616c617465737461","State":"0x20a16af820a970e455cec42ae8b3590c","Framed-MTU":1300,"Tunnel-Medium-Type":"IEEE-802","NAS-IP-Address":"192.168.16.72","Tunnel-Type":"VLAN","Called-Station-Id":"2c:57:41:d1:32:60:apra","NAS-Identifier":"wlc01.apra.it","Event-Timestamp":"Oct 16 2023 12:22:49 CEST","PacketFence-Domain":"APRA","Calling-Station-Id":"48:60:5f:82:05:7f","Airespace-Wlan-Id":2,"FreeRADIUS-Proxied-To":"127.0.0.1","Location-Capable":"Civic-Location","Tunnel-Private-Group-Id":"113","PacketFence-Radius-Ip":"192.168.16.200","User-Name":"g.malatesta","NAS-Port":1,"Chargeable-User-Identity":"0x00","Acct-Session-Id":"652cf2d9\\/48:60:5f:82:05:7f\\/3842","NAS-Port-Type":"Wireless-802.11","Service-Type":"Framed-User","Module-Failure-Message":["chrooted_mschap: Program returned code (1) and output The
attempted
logon
is
invalid.
This
is
either
due
to
a
bad
username
or
authentication
information.
(0xc000006d)","chrooted_mschap: External script says: The attempted logon is invalid. This is either due to a bad username or authentication information. (0xc000006d)","chrooted_mschap: MS-CHAP2-Response is incorrect"],"User-Password":"******"},{"MS-CHAP-Error":"\bE=691 R=0 C=d1e0c998555c3306c722fa2fa24f683c V=3 M=Authentication rejected","EAP-Message":"0x04080004","Message-Authenticator":"0x00000000000000000000000000000000"},{"Auth-Type":"eap"}]

[jrouzierinverse]

What is the version of freeradius you have? rpm -q freeradius

[cmammoli]

[root@srvpf ~]# rpm -q freeradius freeradius-3.2.2-1.el8.x86_64

[cmammoli]

Updated today and I can see the logs are stored in redis as base64. Anyway still does not work:

[root@srvpf ~]# /usr/local/pf/sbin/pfcron flush_radius_audit_log
panic: runtime error: index out of range [0] with length 0

goroutine 1 [running]:
github.com/inverse-inc/packetfence/go/cron.(*FlushRadiusAuditLogJob).Run(0xc0000d8000)
        /root/rpmbuild/centos-8/BUILD/packetfence-13.0.0/go/cron/flush_radius_audit_log_job.go:65 +0x745
main.runJobNow({0x7ffdf2e6b55c, 0x16}, 0x950068d108?)
        /root/rpmbuild/centos-8/BUILD/packetfence-13.0.0/go/cmd/pfcron/main.go:108 +0x304
main.main()
        /root/rpmbuild/centos-8/BUILD/packetfence-13.0.0/go/cmd/pfcron/main.go:153 +0x1c5

[cmammoli]

Do I need to file a new issue?

Regards

[fdurand]

We created new freeradius packages that fix the issue. They will be available soon

[BobDubbya]

We created new freeradius packages that fix the issue. They will be available soon

Any update on when they'll be released?

[fdurand]

the new freeradius packages are in the repository, You can do a apt update / apt upgrade

[BiasF]

Sadly lo change, Audit logs are still not working (only for eduroam).

[fdurand]

ok so it's not the same thing since for eduroam we still use the ols way to store in the radius audit log. Can you reopen a issue for that ?

[BiasF]

hi,

I think you misunderstand. Eduroam is working and all other audit logs still not working ;-) All packet updates are installed.

[BobDubbya]

Rebuilt packetfence server yesterday, radius logs were working. Did upgrade as prescribed, radius logs no longer working.

What logs can I provide to assist in getting this issue resolved?