Hello, I have a new setup using PF 12.2 (I have been using other PF versions with no problem so far) and im seeing a strange behavior. I have a "relatively complex" login flow, but nothing major (and the same setup used in other PF versions / instances). Users are authenticating against google workspace LDAP and I am now using the "baseDn" filter to match users against different OUs on google.
the weird thing is that for each login attempt, I see multiple queries in the logs (I have not dumpled the LDAP traffic itself). But in fact, the repeated queries take "so long" that the portal errors out with 502 code (im assuming timeout). I had disabled the cache option in the ldap source, enabling it did help a bit, but the multiple lookups still seem to be occurring. below is the packetfence.log for a login attempt for a user that matched the first rule of the authentication chain (belong to the group "wifi-it" and assign the proper role). This log was with the "cache" option DISABLED. Aug 8 18:32:56 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found authentication source(s) : 'mariaguadalupe-ldap' for realm 'mariaguadalupe.org.ar' (pf::config::util::filter_authentication_sources) Aug 8 18:32:56 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Authenticating user using sources : mariaguadalupe-ldap (captiveportal::PacketFence::DynamicRouting::Module::Authentication::Login::authenticate) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] [mariaguadalupe-ldap] Authentication successful for mediatel (pf::Authentication::Source::LDAPSource::authenticate) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Authentication successful for mediatel in source mariaguadalupe-ldap (GoogleWorkspaceLDAP) (pf::authentication::authenticate) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] User media...@mariaguadalupe.org.ar has authenticated on the portal. (captiveportal::PacketFence::DynamicRouting::Module::_username_set) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found source mariaguadalupe-ldap in session. (Class::MOP::Class:::around) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found source mariaguadalupe-ldap in session. (Class::MOP::Class:::around) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Successfully authenticated media...@mariaguadalupe.org.ar (captiveportal::PacketFence::DynamicRouting::Module::Authentication::Login::authenticate) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found source mariaguadalupe-ldap in session. (Class::MOP::Class:::around) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found source mariaguadalupe-ldap in session. (Class::MOP::Class:::around) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found source mariaguadalupe-ldap in session. (Class::MOP::Class:::around) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) WARN: [mac:00:11:22:33:44:55] Calling match with empty/invalid rule class. Defaulting to 'authentication' (pf::authentication::match) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Using sources mariaguadalupe-ldap for matching (pf::authentication::match) Aug 8 18:32:59 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) WARN: [mac:00:11:22:33:44:55] [mariaguadalupe-ldap wifi-it] Searching for (&(uid=mediatel)(memberOf=cn=wifi-it,ou=Groups,dc=mariaguadalupe,dc=org,dc=ar)), from ou=Users,dc= mariaguadalupe,dc=org,dc=ar, with scope sub (pf::Authentication::Source::LDAPSource::match_in_subclass) Aug 8 18:32:59 mdg pfqueue[17889]: pfqueue(17889) INFO: [mac:unknown] Already did a person lookup for media...@mariaguadalupe.org.ar (pf::lookup::person::lookup_person) Aug 8 18:33:01 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (wifi-it) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match_rule) Aug 8 18:33:01 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (wifi-it) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match) Aug 8 18:33:01 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found source mariaguadalupe-ldap in session. (Class::MOP::Class:::around) Aug 8 18:33:01 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) WARN: [mac:00:11:22:33:44:55] Calling match with empty/invalid rule class. Defaulting to 'authentication' (pf::authentication::match) Aug 8 18:33:01 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Using sources mariaguadalupe-ldap for matching (pf::authentication::match) Aug 8 18:33:01 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) WARN: [mac:00:11:22:33:44:55] [mariaguadalupe-ldap wifi-it] Searching for (&(uid=mediatel)(memberOf=cn=wifi-it,ou=Groups,dc=mariaguadalupe,dc=org,dc=ar)), from ou=Users,dc= mariaguadalupe,dc=org,dc=ar, with scope sub (pf::Authentication::Source::LDAPSource::match_in_subclass) Aug 8 18:33:02 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (wifi-it) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match_rule) Aug 8 18:33:02 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (wifi-it) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match) Aug 8 18:33:02 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found source mariaguadalupe-ldap in session. (Class::MOP::Class:::around) Aug 8 18:33:02 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Using sources mariaguadalupe-ldap for matching (pf::authentication::match) Aug 8 18:33:02 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) WARN: [mac:00:11:22:33:44:55] [mariaguadalupe-ldap IT-admin] Searching for (&(uid=mediatel)(memberOf=cn=wifi-it,ou=Groups,dc=mariaguadalupe,dc=org,dc=ar)), from ou=Users,dc= mariaguadalupe,dc=org,dc=ar, with scope sub (pf::Authentication::Source::LDAPSource::match_in_subclass) Aug 8 18:33:04 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (IT-admin) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match_rule) Aug 8 18:33:04 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (IT-admin) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match) Aug 8 18:33:04 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found source mariaguadalupe-ldap in session. (Class::MOP::Class:::around) Aug 8 18:33:04 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) WARN: [mac:00:11:22:33:44:55] Calling match with empty/invalid rule class. Defaulting to 'authentication' (pf::authentication::match) Aug 8 18:33:04 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Using sources mariaguadalupe-ldap for matching (pf::authentication::match) Aug 8 18:33:04 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) WARN: [mac:00:11:22:33:44:55] [mariaguadalupe-ldap wifi-it] Searching for (&(uid=mediatel)(memberOf=cn=wifi-it,ou=Groups,dc=mariaguadalupe,dc=org,dc=ar)), from ou=Users,dc= mariaguadalupe,dc=org,dc=ar, with scope sub (pf::Authentication::Source::LDAPSource::match_in_subclass) Aug 8 18:33:04 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] LDAP testing connection (pf::LDAP::expire_if) Aug 8 18:33:05 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (wifi-it) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match_rule) Aug 8 18:33:05 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (wifi-it) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match) Aug 8 18:33:05 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found source mariaguadalupe-ldap in session. (Class::MOP::Class:::around) Aug 8 18:33:05 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) WARN: [mac:00:11:22:33:44:55] Calling match with empty/invalid rule class. Defaulting to 'authentication' (pf::authentication::match) Aug 8 18:33:05 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Using sources mariaguadalupe-ldap for matching (pf::authentication::match) Aug 8 18:33:05 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) WARN: [mac:00:11:22:33:44:55] [mariaguadalupe-ldap wifi-it] Searching for (&(uid=mediatel)(memberOf=cn=wifi-it,ou=Groups,dc=mariaguadalupe,dc=org,dc=ar)), from ou=Users,dc= mariaguadalupe,dc=org,dc=ar, with scope sub (pf::Authentication::Source::LDAPSource::match_in_subclass) Aug 8 18:33:07 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (wifi-it) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match_rule) Aug 8 18:33:07 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (wifi-it) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match) Aug 8 18:33:07 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found source mariaguadalupe-ldap in session. (Class::MOP::Class:::around) Aug 8 18:33:07 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) WARN: [mac:00:11:22:33:44:55] Calling match with empty/invalid rule class. Defaulting to 'authentication' (pf::authentication::match) Aug 8 18:33:07 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Using sources mariaguadalupe-ldap for matching (pf::authentication::match) Aug 8 18:33:07 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) WARN: [mac:00:11:22:33:44:55] [mariaguadalupe-ldap wifi-it] Searching for (&(uid=mediatel)(memberOf=cn=wifi-it,ou=Groups,dc=mariaguadalupe,dc=org,dc=ar)), from ou=Users,dc= mariaguadalupe,dc=org,dc=ar, with scope sub (pf::Authentication::Source::LDAPSource::match_in_subclass) Aug 8 18:33:08 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (wifi-it) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match_rule) Aug 8 18:33:08 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Matched rule (wifi-it) in source mariaguadalupe-ldap, returning actions. (pf::Authentication::Source::match) Aug 8 18:33:08 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] Found source mariaguadalupe-ldap in session. (Class::MOP::Class:::around) Aug 8 18:33:08 mdg httpd.portal-docker-wrapper[6092]: httpd.portal(23) INFO: [mac:00:11:22:33:44:55] security_event 1300003 force-closed for 00:11:22:33:44:55 (pf::security_event::security_event_force_close) I find it a bit surprising to see 10 instances of the event "Matched rule (wifi-it) in source mariaguadalupe-ldap". In my view, it should be matching only once, shouldnt't it? I also see 6 ldap queries (identical): [mariaguadalupe-ldap wifi-it] Searching for (&(uid=mediatel)(memberOf=cn=wifi-it, (mariaguadalupe-ldap is the ldap source and "wifi-it" is the first rule of the authentication actions, assigning a role / access duration. using a different user that matches the "last resort" rule (the 4th) I also see, with the cache enabled I see also 6 or seven "Matched rule" events... I dont want to spam with more logs .. but this seems to be quite a change from what I used to see in PF11 and earlier. Also, even if this is the registration portal login, I see events matching the rules for Authorization (which, AFAIK, should only matter for logins onto the PF GUI / mangament interface). thanks in advance!
_______________________________________________ PacketFence-users mailing list PacketFence-users@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/packetfence-users
