Audit log empty after upgrading to 13.0 #7853

cmammoli · 2023-10-09T15:07:28Z

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:

Upgrade to PF13
Perform a bunch of 802.1x/portal authentications
Go to "auditing"
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

The text was updated successfully, but these errors were encountered:

jrouzierinverse · 2023-10-10T17:53:35Z

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

jrouzierinverse · 2023-10-10T18:18:18Z

Is this on Debian or RHEL?

cmammoli · 2023-10-12T08:19:22Z

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 · 2023-10-13T06:29:35Z

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 · 2023-10-16T08:25:47Z

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 · 2023-10-16T11:04:35Z

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

cmammoli · 2023-10-16T12:19:16Z

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

cmammoli · 2023-10-20T07:56:35Z

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 · 2023-10-30T10:52:37Z

Do I need to file a new issue?

Regards

fdurand · 2023-10-30T13:07:50Z

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

BobDubbya · 2023-11-14T18:36:16Z

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

Any update on when they'll be released?

fdurand · 2023-11-14T21:15:14Z

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

BiasF · 2023-11-15T08:31:28Z

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

fdurand · 2023-11-15T14:13:39Z

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 · 2023-11-15T17:13:31Z

hi,

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

BobDubbya · 2023-11-15T17:29:29Z

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?

cmammoli added the Type: Bug label Oct 9, 2023

fdurand assigned jrouzierinverse Oct 10, 2023

fdurand added the Priority: Critical label Oct 10, 2023

fdurand added this to the +1 (patch release) milestone Oct 10, 2023

satkunas mentioned this issue Oct 18, 2023

Use the new RADIUS Audit Log method for eduroam and cli radius server. #7866

Open

jrouzierinverse mentioned this issue Oct 19, 2023

base64 json before inserting into redis #7870

Merged

4 tasks

fdurand closed this as completed in #7870 Oct 19, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Audit log empty after upgrading to 13.0 #7853

Audit log empty after upgrading to 13.0 #7853

cmammoli commented Oct 9, 2023

jrouzierinverse commented Oct 10, 2023

jrouzierinverse commented Oct 10, 2023

cmammoli commented Oct 12, 2023

BiasF commented Oct 13, 2023 •

edited

Loading

cmammoli commented Oct 16, 2023

jrouzierinverse commented Oct 16, 2023

cmammoli commented Oct 16, 2023

cmammoli commented Oct 20, 2023

cmammoli commented Oct 30, 2023

fdurand commented Oct 30, 2023

BobDubbya commented Nov 14, 2023

fdurand commented Nov 14, 2023

BiasF commented Nov 15, 2023

fdurand commented Nov 15, 2023

BiasF commented Nov 15, 2023

BobDubbya commented Nov 15, 2023

Audit log empty after upgrading to 13.0 #7853

Audit log empty after upgrading to 13.0 #7853

Comments

cmammoli commented Oct 9, 2023

jrouzierinverse commented Oct 10, 2023

jrouzierinverse commented Oct 10, 2023

cmammoli commented Oct 12, 2023

BiasF commented Oct 13, 2023 • edited Loading

cmammoli commented Oct 16, 2023

jrouzierinverse commented Oct 16, 2023

cmammoli commented Oct 16, 2023

cmammoli commented Oct 20, 2023

cmammoli commented Oct 30, 2023

fdurand commented Oct 30, 2023

BobDubbya commented Nov 14, 2023

fdurand commented Nov 14, 2023

BiasF commented Nov 15, 2023

fdurand commented Nov 15, 2023

BiasF commented Nov 15, 2023

BobDubbya commented Nov 15, 2023

BiasF commented Oct 13, 2023 •

edited

Loading