Error: Ignoring duplicate packet, LDAP performance

[uj2.hahn at posteo.de]

Hi, freeradius team!
I know, this "Ignoring duplicate packet" topic has been discussed for a 
long time again and again.
I see that in a special configuration:
- FreeRADIUS Version 3.0.17 on Ubuntu
- ActiveDirectory on Winserver 2012 R2
- authentication via ntlm_auth
- post-auth via LDAP (group ownership etc)
- 15 brand-new Cisco/Meraki-WLAN-APs in network
- all Cisco/Meraki-WLAN-APs are controlled by a central web-based Meraki 
dashboard

Everything works fine, there are no user complaints so far.
BUT: The central Meraki dashboard has a built-in test function to check 
all managed NAS if they are able to communicate
with radius server. So I have to provide an existing user/password and 
the dashboard triggers each NAS to check for
freeradius authentication with same credentials.
In this scenario I run into the "Ignoring duplicate packet" issue (see 
freeradius log part below)
which let the Meraki dashboard reports some NAS as failing. The count of 
failing NASs and the failing NASs are varying .
However when I disable the LDAP post-auth section everything is fine.

Wed Feb 26 14:21:05 2020 : Info: rlm_ldap (ldap): Opening additional 
connection (17641), 1 of 30 pending slots used
Wed Feb 26 14:21:05 2020 : Info: rlm_ldap (ldap): Deleting connection 
(17640) - Was referred to a different LDAP server
Wed Feb 26 14:21:05 2020 : Info: Need 1 more connections to reach min 
connections (3)
Wed Feb 26 14:21:05 2020 : Info: rlm_ldap (ldap): Opening additional 
connection (17642), 2 of 31 pending slots used
Wed Feb 26 14:21:05 2020 : Error: (69437) Ignoring duplicate packet from 
client ZI-110 port 54766 - ID: 8 due to unfinished request in component 
post-auth module ldap
Wed Feb 26 14:21:05 2020 : Error: (69438) Ignoring duplicate packet from 
client ZI-112 port 42248 - ID: 8 due to unfinished request in component 
post-auth module ldap
Wed Feb 26 14:21:05 2020 : Info: rlm_ldap (ldap): Deleting connection 
(17638) - Was referred to a different LDAP server
Wed Feb 26 14:21:07 2020 : Info: rlm_ldap (ldap): Opening additional 
connection (17643), 1 of 30 pending slots used
Wed Feb 26 14:21:07 2020 : Error: (69446) Ignoring duplicate packet from 
client ZI-120 port 58022 - ID: 6 due to unfinished request in component 
authenticate module eap_peap
Wed Feb 26 14:21:07 2020 : Error: (69453) Ignoring duplicate packet from 
client ZI-216 port 37434 - ID: 6 due to unfinished request in component 
authenticate module eap_peap
Wed Feb 26 14:21:08 2020 : Error: (69460) Ignoring duplicate packet from 
client ZI-012 port 49893 - ID: 6 due to unfinished request in component 
authenticate module eap_peap
Wed Feb 26 14:21:08 2020 : Info: rlm_ldap (ldap): Deleting connection 
(17642) - Was referred to a different LDAP server
Wed Feb 26 14:21:08 2020 : Info: Need 1 more connections to reach min 
connections (3)
Wed Feb 26 14:21:08 2020 : Info: rlm_ldap (ldap): Opening additional 
connection (17644), 1 of 30 pending slots used
Wed Feb 26 14:21:08 2020 : Info: rlm_ldap (ldap): Deleting connection 
(17641) - Was referred to a different LDAP server
Wed Feb 26 14:21:08 2020 : Info: rlm_ldap (ldap): Opening additional 
connection (17645), 1 of 30 pending slots used
Wed Feb 26 14:21:09 2020 : Info: rlm_ldap (ldap): Deleting connection 
(17643) - Was referred to a different LDAP server

I'm pretty sure the root cause is related to general network and/or LDAP 
performance.
Actions I will take are:
- let network admin check the network and DC/AD server performance
- review my freeradius LDAP queries if they are specific enough 
(reducing the amount of data they generate)

But I have some questions to freeradius team related to that:
I have a single freeradius server and a single DC/AD server.
1) Why does freeradius open and close LDAP connections pretty often? 
Isn't one permanently open connection good enough?
2)  What does this message mean: Info: rlm_ldap (ldap): Deleting 
connection (17640) - Was referred to a different LDAP server
      There is just one LDAP server!
      I started  a debug session and found this matching part in debug log:

     (25) ldap: User object found at DN "CN=jasmin 
hahn,OU=Schueler,DC=moritz,DC=local"
     (25) ldap: EXPAND (samaccountname=%{mschap:User-Name})
     (25) ldap:    --> (samaccountname=jasmin-hahn)
     (25) ldap: Waiting for bind result...
     (25) ldap: Bind successful
     (25) ldap: Performing search in "DC=moritz,DC=local" with filter 
"(samaccountname=jasmin-hahn)", scope "sub"
     (25) ldap: Waiting for search result...
     rlm_ldap (ldap): Rebinding to URL 
ldap://ForestDnsZones.moritz.local/DC=ForestDnsZones,DC=moritz,DC=local
     rlm_ldap (ldap): Waiting for bind result...
     rlm_ldap (ldap): Rebinding to URL 
ldap://DomainDnsZones.moritz.local/DC=DomainDnsZones,DC=moritz,DC=local
     rlm_ldap (ldap): Waiting for bind result...
     rlm_ldap (ldap): Rebinding to URL 
ldap://moritz.local/CN=Configuration,DC=moritz,DC=local
     rlm_ldap (ldap): Waiting for bind result...
     rlm_ldap (ldap): Bind successful
     rlm_ldap (ldap): Bind successful
     rlm_ldap (ldap): Bind successful
     (25) ldap: Adding cacheable group object memberships
     (25) ldap:   &control:LDAP-Group += "OU=Schueler"
     (25) ldap: Processing user attributes
     (25) ldap: WARNING: No "known good" password added. Ensure the 
admin user has permission to read the password attribute
     (25) ldap: WARNING: PAP authentication will *NOT* work with Active 
Directory (if that is what you were trying to configure)
*rlm_ldap (ldap): Deleting connection (3) - Was referred to a different 
LDAP server*

     (I'm aware I cannot get passwd from AD, that's why I use ntlm_auth. 
This is not the topic I want to ask here. Or is it related??)

3) In my special case (self test by Meraki dashboard) I check same user 
from all NASs within a short timeframe.
     So freeradius should provide always same feedback. Could the 
freeradius flow be shortened by a cache mechanism?

Thanks a lot!
Uwe