search

inverse-inc / packetfence

PacketFence is a fully supported, trusted, Free and Open Source network access control (NAC) solution. Boasting an impressive feature set including a captive-portal for registration and remediation, centralized wired and wireless management, powerful BYOD management options, 802.1X support, layer-2 isolation of problematic devices; PacketFence can be used to effectively secure networks small to very large heterogeneous networks.
https://packetfence.org
GNU General Public License v2.0
1.39k stars 291 forks source link

tests: Move redis to DB #7775

Closed JeGoi closed 1 year ago

JeGoi commented 1 year ago

Describe the problem

            • move_from_redis_to_db FAILURE
    Testcase "pfcron_command_line", step #0: Assertion "result.code ShouldEqual 0" failed. expected: 0  got: 2 (:0)
    Testcase "pfcron_flush_radius_audit_log", step #0: failed (:0)
    Testcase "move_from_redis_to_db", step #0: failed (/usr/local/pf/t/venom/test_suites/wired_dot1x_eap_tls_manual/91_check_radius_audit_log.yml:10)

Mandatory informations

Symptoms How the problem can be identified if it appears again ? Rerun

Possible fix Check logs Add retry with delay

JeGoi commented 1 year ago

Not sure how but:

Jul 24 14:40:40.048ESC[36m [INFO] [Check RADIUS audit log] [move_from_redis_to_db] [pfcron_command_line] ESC[0mStep #0 content is: "{\"script\":\" /usr/local/pf/sbin/pfcron flush_radius_audit_log\",\"typ
e\":\"exec\"}"
Jul 24 14:40:40.083ESC[37m [DEBU] [Check RADIUS audit log] [move_from_redis_to_db] [exec] ESC[0mresult of runTestStepExecutor: {Systemout: SystemoutJSON:<nil> Systemerr:panic: runtime error: index out of range [1] with length 0

goroutine 1 [running]:
github.com/inverse-inc/packetfence/go/cron.(*FlushRadiusAuditLogJob).argsFromEntry(0xc0000fa500?, {0x0, 0x0, 0xc0000fa4b0?})
        /builds/inverse-inc/packetfence/go/cron/flush_radius_audit_log_job.go:167 +0x1058
github.com/inverse-inc/packetfence/go/cron.(*FlushRadiusAuditLogJob).buildQuery(0xc0000c9b38?, {0xc0000ac738, 0x1, 0xc0000a3da0?})
        /builds/inverse-inc/packetfence/go/cron/flush_radius_audit_log_job.go:158 +0x1e5
github.com/inverse-inc/packetfence/go/cron.(*FlushRadiusAuditLogJob).flushLogs(0xc00017b000?, {0xc0000ac738?, 0x1000?, 0x6feaa0?})
        /builds/inverse-inc/packetfence/go/cron/flush_radius_audit_log_job.go:75 +0x3f
github.com/inverse-inc/packetfence/go/cron.(*FlushRadiusAuditLogJob).Run(0xc0000eff10)
        /builds/inverse-inc/packetfence/go/cron/flush_radius_audit_log_job.go:63 +0x22f
main.runJobNow({0x7ffc14c80a6f, 0x16}, 0xf8aee56908?)
        /builds/inverse-inc/packetfence/go/cmd/pfcron/main.go:108 +0x304
main.main()
        /builds/inverse-inc/packetfence/go/cmd/pfcron/main.go:153 +0x1c5 SystemerrJSON:<nil> Err: Code:2 TimeSeconds:0.027987397}

Looks like an out of range issue in a loop... @jrouzierinverse any idea on that?

JeGoi commented 1 year ago

https://gitlab.com/inverse-inc/packetfence/-/jobs/4731111381

wired_dot1x_eap_tls_scep wired_dot1x_eap_tls_manual (due to "PacketFence-Role":{"type":"string","value":"dot1x_eap_tls_manual"})

Every 2.0s: redis-cli --raw LRANGE RADIUS_AUDIT_LOG 0 -1                                                                                                                 pfel8dev: Mon Jul 24 15:10:56 2023

["Accept",{"User-Name":{"type":"string","value":"inverse"},"NAS-IP-Address":{"type":"ipaddr","value":"172.18.200.201"},"NAS-Port":{"type":"integer","value":8},"Service-Type":{"type":"integer","value":"Fr
amed-User"},"Framed-MTU":{"type":"integer","value":1400},"State":{"type":"octets","value":"0xd4dcbfb7d2b2b2d818c3a89b3ee862e3"},"Called-Station-Id":{"type":"string","value":"44-38-39-00-00-12:"},"Calling
-Station-Id":{"type":"string","value":"00:03:00:11:11:01"},"NAS-Identifier":{"type":"string","value":"localhost"},"NAS-Port-Type":{"type":"integer","value":"Ethernet"},"Acct-Session-Id":{"type":"string",
"value":"5E985F6165CE79DA"},"Event-Timestamp":{"type":"date","value":"Jul 24 2023 15:10:43 UTC"},"EAP-Message":{"type":"octets","value":"0x026e00060d00"},"Message-Authenticator":{"type":"octets","value":
"0x7199385d306785465df1254d8f064146"},"NAS-Port-Id":{"type":"string","value":"swp12"},"EAP-Type":{"type":"integer","value":"TLS"},"Stripped-User-Name":{"type":"string","value":"inverse"},"Realm":{"type":
"string","value":"null"},"FreeRADIUS-Client-IP-Address":{"type":"ipaddr","value":"172.18.200.201"},"TLS-Cert-Serial":{"type":"string","value":"01"},"TLS-Cert-Expiration":{"type":"string","value":"2508121
50641Z"},"TLS-Cert-Issuer":{"type":"string","value":"\\/C=CA\\/ST=Quebec\\/L=Montreal\\/O=Inverse\\/OU=PacketFence\\/CN=InverseCA1"},"TLS-Cert-Subject":{"type":"string","value":"\\/C=CA\\/ST=Quebec\\/L=M
ontreal\\/O=Inverse\\/OU=PacketFence\\/CN=InverseCA1"},"TLS-Cert-Common-Name":{"type":"string","value":"InverseCA1"},"TLS-Cert-Subject-Alt-Name-Email":{"type":"string","value":"mailhog@example.lan"},"TLS
-Cert-Valid-Since":{"type":"string","value":"230724150641Z"},"TLS-Client-Cert-Serial":{"type":"string","value":"03"},"TLS-Client-Cert-Expiration":{"type":"string","value":"250812150727Z"},"TLS-Client-Cer
t-Issuer":{"type":"string","value":"\\/C=CA\\/ST=Quebec\\/L=Montreal\\/O=Inverse\\/OU=PacketFence\\/CN=InverseCA1"},"TLS-Client-Cert-Subject":{"type":"string","value":"\\/C=CA\\/ST=Quebec\\/L=Montreal\\/
O=Inv,{"MS-MPPE-Recv-Key":{"type":"octets","value":"0xb4fc3e6bf4099144b5603ab2d4eebaa34c2f1817cdc20d172442b1e3744830ea"},"MS-MPPE-Send-Key":{"type":"octets","value":"0x11ebf90a79b97c1747cce894fcff7e32318
930b31d2f5d15649510e6f499c2c8"},"EAP-MSK":{"type":"octets","value":"0xb4fc3e6bf4099144b5603ab2d4eebaa34c2f1817cdc20d172442b1e3744830ea11ebf90a79b97c1747cce894fcff7e32318930b31d2f5d15649510e6f499c2c8"},"E
AP-EMSK":{"type":"octets","value":"0x8df09a15d7e72a8bde9e08f81b44ed284c7002b3432d8a084a222e8ad136dc035c87d380a54198e55b0b7372b3b4edd8536ffc9ac076eecdae8449e2f46140fd"},"EAP-Session-Id":{"type":"octets","
value":"0x0d12dd7ec9243ddba81d1960d37422c1238d0dfcb34e8b770c1233ed76d983c981de5bcf569a88557a02958f042e72208a8a846bc33db47b532e47e9bf35f2ccec"},"EAP-Message":{"type":"octets","value":"0x036e0004"},"Messag
e-Authenticator":{"type":"octets","value":"0x00000000000000000000000000000000"},"User-Name":{"type":"string","value":"inverse"},"REST-HTTP-Status-Code":{"type":"integer","value":200},"Tunnel-Medium-Type"
:{"type":"integer","value":"IEEE-802"},"Tunnel-Type":{"type":"integer","value":"VLAN"},"Tunnel-Private-Group-Id":{"type":"string","value":"100"}},{"PacketFence-Switch-Id":{"type":"string","value":"44:38:
39:00:00:12"},"PacketFence-Switch-Mac":{"type":"string","value":"44:38:39:00:00:12"},"PacketFence-Switch-Ip-Address":{"type":"string","value":"172.18.200.201"},"PacketFence-IfIndex":{"type":"string","val
ue":"8"},"PacketFence-Connection-Type":{"type":"string","value":"Ethernet-EAP"},"Auth-Type":{"type":"integer","value":"eap"},"PacketFence-Role":{"type":"string","value":"dot1x_eap_tls_manual"},"PacketFen
ce-Status":{"type":"string","value":"reg"},"PacketFence-Profile":{"type":"string","value":"catch_dot1x_wired_eap_tls"},"PacketFence-Source":{"type":"string","value":"eaptls"},"PacketFence-AutoReg":{"type
":"string","value":"1"},"PacketFence-IsPhone":{"type":"string","value":""},"PacketFence-Request-Time":{"type":"integer","value":1}}]

wired_dot1x_eap_tls_pki (100% sure)

Every 2.0s: redis-cli --raw LRANGE RADIUS_AUDIT_LOG 0 -1                                                                                                                 pfel8dev: Mon Jul 24 15:26:55 2023

["Reject",{"User-Name":{"type":"string","value":"inverse"},"NAS-IP-Address":{"type":"ipaddr","value":"172.18.200.201"},"NAS-Port":{"type":"integer","value":8},"Service-Type":{"type":"integer","value":"Fr
amed-User"},"Framed-MTU":{"type":"integer","value":1400},"State":{"type":"octets","value":"0xa96f2d2faf0120d7d515db4dacabb4a0"},"Called-Station-Id":{"type":"string","value":"44-38-39-00-00-12:"},"Calling
-Station-Id":{"type":"string","value":"00:03:00:11:11:01"},"NAS-Identifier":{"type":"string","value":"localhost"},"NAS-Port-Type":{"type":"integer","value":"Ethernet"},"Acct-Session-Id":{"type":"string",
"value":"319744E860FFF92A"},"Event-Timestamp":{"type":"date","value":"Jul 24 2023 15:26:40 UTC"},"EAP-Message":{"type":"octets","value":"0x026e00060d00"},"Message-Authenticator":{"type":"octets","value":
"0xcae836223544e23799f4d6a9930aa2f1"},"NAS-Port-Id":{"type":"string","value":"swp12"},"EAP-Type":{"type":"integer","value":"TLS"},"Stripped-User-Name":{"type":"string","value":"inverse"},"Realm":{"type":
"string","value":"null"},"FreeRADIUS-Client-IP-Address":{"type":"ipaddr","value":"172.18.200.201"},"TLS-Cert-Serial":{"type":"string","value":"04"},"TLS-Cert-Expiration":{"type":"string","value":"2508121
52154Z"},"TLS-Cert-Issuer":{"type":"string","value":"\\/C=CA\\/ST=Quebec\\/L=Montreal\\/O=Inverse\\/OU=PacketFence\\/CN=InverseCA3"},"TLS-Cert-Subject":{"type":"string","value":"\\/C=CA\\/ST=Quebec\\/L=M
ontreal\\/O=Inverse\\/OU=PacketFence\\/CN=InverseCA3"},"TLS-Cert-Common-Name":{"type":"string","value":"InverseCA3"},"TLS-Cert-Subject-Alt-Name-Email":{"type":"string","value":"mailhog@example.lan"},"TLS
-Cert-Valid-Since":{"type":"string","value":"230724152154Z"},"TLS-Client-Cert-Serial":{"type":"string","value":"03"},"TLS-Client-Cert-Expiration":{"type":"string","value":"250812152240Z"},"TLS-Client-Cer
t-Issuer":{"type":"string","value":"\\/C=CA\\/ST=Quebec\\/L=Montreal\\/O=Inverse\\/OU=PacketFence\\/CN=InverseCA3"},"TLS-Client-Cert-Subject":{"type":"string","value":"\\/C=CA\\/ST=Quebec\\/L=Montreal\\/
O=Inv,{"MS-MPPE-Recv-Key":{"type":"octets","value":"0x33d68daee4bd9f78d22480e8cf189e91043894a0be4cefbe336ca837aed9999c"},"MS-MPPE-Send-Key":{"type":"octets","value":"0xc1b82f32a758562792221a73343264d4910
a367fd2801e346d21e7316137971f"},"EAP-MSK":{"type":"octets","value":"0x33d68daee4bd9f78d22480e8cf189e91043894a0be4cefbe336ca837aed9999cc1b82f32a758562792221a73343264d4910a367fd2801e346d21e7316137971f"},"E
AP-EMSK":{"type":"octets","value":"0xdc4aa146f3deaf5ea53bc80a81b0773bbbf4954eb248eafdc830dae938a0b1d63451c75c557b6d623fc1cd8536b4e46405ef8520755d60157efa657d7e2303a0"},"EAP-Session-Id":{"type":"octets","
value":"0x0df59ad06e75e8b3fa6e23a4affd220e27daa8a144a4ef413b55d49fba51a2d4610f7129a027d860da1597b19550ba08737fbeedc510407f5aa387f6f33b559114"},"EAP-Message":{"type":"octets","value":"0x036e0004"},"Messag
e-Authenticator":{"type":"octets","value":"0x00000000000000000000000000000000"},"User-Name":{"type":"string","value":"inverse"}},{"Auth-Type":{"type":"integer","value":"eap"},"PacketFence-Request-Time":{
"type":"integer","value":0}}]
JeGoi commented 1 year ago 
id  created_at  mac ip  computer_name   user_name   stripped_user_name  realm   event_type  switch_id   switch_mac  switch_ip_address   radius_source_ip_address    called_station_id   calling_station_id  nas_port_type   ssid    nas_port_id ifindex nas_port    connection_type nas_ip_address  nas_identifier  auth_status reason  auth_type   eap_type    role    node_status profile source  auto_reg    is_phone    pf_domain   uuid    radius_request  radius_reply    request_time    radius_ip
1   2023-07-24 20:46:42 00:03:00:11:11:01   N/A N/A inverse inverse null    Radius-Access-Request   44:38:39:00:00:12   44:38:39:00:00:12   172.18.200.201  N/A 44-38-39-00-00-12:  00:03:00:11:11:01   Ethernet        swp12   8   8   Ethernet-EAP    172.18.200.201  localhost   Accept      eap TLS dot1x_eap_tls_manual    reg catch_dot1x_wired_eap_tls   eaptls  1               Acct-Session-Id =3D =226DDD7B18E619DAFA=22=2C=0ACalled-Station-Id =3D =2244-38-39-00-00-12:=22=2C=0ACalling-Station-Id =3D =2200:03:00:11:11:01=22=2C=0AEAP-Message =3D =220x026e00060d00=22=2C=0AEAP-Type =3D =22TLS=22=2C=0AEvent-Timestamp =3D =22Jul 24 2023 20:46:18 UTC=22=2C=0AFramed-MTU =3D =221400=22=2C=0AFreeRADIUS-Client-IP-Address =3D =22172.18.200.201=22=2C=0AMessage-Authenticator =3D =220xccb4f10903bd8f5899852e1354486a48=22=2C=0ANAS-IP-Address =3D =22172.18.200.201=22=2C=0ANAS-Identifier =3D =22localhost=22=2C=0ANAS-Port =3D =228=22=2C=0ANAS-Port-Id =3D =22swp12=22=2C=0ANAS-Port-Type =3D =22Ethernet=22=2C=0APacketFence-KeyBalanced =3D =229071115b8a75df4b305af8c2cbeab289=22=2C=0APacketFence-Radius-Ip =3D =22172.18.200.12=22=2C=0ARealm =3D =22null=22=2C=0AService-Type =3D =22Framed-User=22=2C=0AState =3D =220xf631cfb0f05fc281606f92f34e1aa8cb=22=2C=0AStripped-User-Name =3D =22inverse=22=2C=0ATLS-Cert-Common-Name =3D =22InverseCA1=22=2C=0ATLS-Cert-Expiration =3D =22250812204218Z=22=2C=0ATLS-Cert-Issuer =3D =22=5C/C=3DCA=5C/ST=3DQuebec=5C/L=3DMontreal=5C/O=3DInverse=5C/OU=3DPacketFence=5C/CN=3DInverseCA1=22=2C=0ATLS-Cert-Serial =3D =2201=22=2C=0ATLS-Cert-Subject =3D =22=5C/C=3DCA=5C/ST=3DQuebec=5C/L=3DMontreal=5C/O=3DInverse=5C/OU=3DPacketFence=5C/CN=3DInverseCA1=22=2C=0ATLS-Cert-Subject-Alt-Name-Email =3D =22mailhog@example.lan=22=2C=0ATLS-Cert-Valid-Since =3D =22230724204218Z=22=2C=0ATLS-Client-Cert-Common-Name =3D =22InverseCA1_user_cert=22=2C=0ATLS-Client-Cert-Expiration =3D =22250812204308Z=22=2C=0ATLS-Client-Cert-Issuer =3D =22=5C/C=3DCA=5C/ST=3DQuebec=5C/L=3DMontreal=5C/O=3DInverse=5C/OU=3DPacketFence=5C/CN=3DInverseCA1=22=2C=0ATLS-Client-Cert-Serial =3D =2203=22=2C=0ATLS-Client-Cert-Subject =3D =22=5C/C=3DCA=5C/ST=3DQuebec=5C/L=3DMontreal=5C/O=3DInverse=5C/OU=3DPacketFence=5C/CN=3DInverseCA1_user_cert=22=2C=0ATLS-Client-Cert-Subject-Alt-Name-Email =3D =22mailhog@example.lan=22=2C=0ATLS-Client-Cert-Valid-Since =3D =22230724204308Z=22=2C=0ATLS-Client-Cert-X509v3-Authority-Key-Identifier =3D =22keyid:3E:3E:62:62:D8:A4:5F:39:C8:85:6E:AD:54:A3:D7:A8:DC:8F:0C:51=0A=22=2C=0ATLS-Client-Cert-X509v3-Extended-Key-Usage =3D =22TLS Web Client Authentication=22=2C=0ATLS-Client-Cert-X509v3-Extended-Key-Usage-OID =3D =221.3.6.1.5.5.7.3.2=22=2C=0ATLS-Client-Cert-X509v3-Subject-Key-Identifier =3D =22E2:A8:DC:D4:6F:BC:E2:09:78:4B:63:62:63:55:87:03:3F:4B:BE:0E=22=2C=0AUser-Name =3D =22inverse=22=2C=0AUser-Password =3D =22=2A=2A=2A=2A=2A=2A=22    EAP-EMSK =3D =220xf24ac09b2f0796cea29acc03cd2453dbce57c2907d7efc17e48faf543db11177eae5ae11f5d6d5b175ea38ec1d4be94f4785f0f227fd98b2500d48a35c12dd29=22=2C=0AEAP-MSK =3D =220x1f8baf42ba6b8b555ecb284f7c51c19e724accd85a6771d9abada8bb01560180ed84c9857523070913a4a77572d7b48db87de7b9641e036784e0c795f2b6e51e=22=2C=0AEAP-Message =3D =220x036e0004=22=2C=0AEAP-Session-Id =3D =220x0ddfd163b88472bbae7a7e6b5d2b20a76100729a0f0d569fb49ea8d2a8ae2c512e015882f3dbf4bb335cb84c24cd31758f5279bc8d66053e5db2b71388b2b9f645=22=2C=0AMS-MPPE-Recv-Key =3D =220x1f8baf42ba6b8b555ecb284f7c51c19e724accd85a6771d9abada8bb01560180=22=2C=0AMS-MPPE-Send-Key =3D =220xed84c9857523070913a4a77572d7b48db87de7b9641e036784e0c795f2b6e51e=22=2C=0AMessage-Authenticator =3D =220x00000000000000000000000000000000=22=2C=0AREST-HTTP-Status-Code =3D =22200=22=2C=0ATunnel-Medium-Type =3D =22IEEE-802=22=2C=0ATunnel-Private-Group-Id =3D =22100=22=2C=0ATunnel-Type =3D =22VLAN=22=2C=0AUser-Name =3D =22inverse=22  0   172.18.200.12

UTF8 issue? from redis to DB Looks like it is not.

JeGoi commented 1 year ago

Looks fine since moved to 3.2.2 and increase buffer size (https://github.com/inverse-inc/freeradius-server/commit/7cbeb6b7f810ed233a2d4ffdc6cc19fdfd671cde)