Re: Release of the IP after the Acct-Stop (ippool)

Hi Alan, In the site-availiable configuration for vpn we have configured several ippools (see below). Each entry with the defined IP ranges for the corresponding department of our university. For example FB1-B (employees Department 1) or FB1-S (students Department 1) The assignment of the correct Ippool based on group memberships works. Only the release of the IP address after the termination of the connection does not work. In the following debug log, the person is assigned an IP address from the DVZ-S area when connecting. However, when the connection is stopped, the IP address is not released again because only the first entry (FB1-B) is checked. After the ippool FB1-B, the next ippool FB1-S is not checked. I hope I was able to explain our mistake better. (2116) Mon Oct 29 15:15:52 2018: Debug: Received Access-Request Id 39 from 193.25.18.219:48008 to 10.100.16.162:2001 length 184 (2116) Mon Oct 29 15:15:52 2018: Debug: User-Name = "user1" (2116) Mon Oct 29 15:15:52 2018: Debug: User-Password = "xxxxxxxxxxxxxx" (2116) Mon Oct 29 15:15:52 2018: Debug: NAS-Port = 202297344 (2116) Mon Oct 29 15:15:52 2018: Debug: Service-Type = Framed-User (2116) Mon Oct 29 15:15:52 2018: Debug: Framed-Protocol = PPP (2116) Mon Oct 29 15:15:52 2018: Debug: Called-Station-Id = "193.25.18.219" (2116) Mon Oct 29 15:15:52 2018: Debug: Calling-Station-Id = "109.90.177.240" (2116) Mon Oct 29 15:15:52 2018: Debug: NAS-Port-Type = Virtual (2116) Mon Oct 29 15:15:52 2018: Debug: Tunnel-Client-Endpoint:0 = "109.90.177.240" (2116) Mon Oct 29 15:15:52 2018: Debug: NAS-IP-Address = 193.25.18.219 (2116) Mon Oct 29 15:15:52 2018: Debug: Cisco-AVPair = "ip:source-ip=109.90.177.240" (2116) Mon Oct 29 15:15:52 2018: Debug: ASA-TunnelGroupName = "xxxxxxx" (2116) Mon Oct 29 15:15:52 2018: Debug: ASA-ClientType = Cisco-VPN-Client-IKEv1 (2116) Mon Oct 29 15:15:52 2018: Debug: # Executing section authorize from file /etc/freeradius/3.0/sites-enabled/vpn (2116) Mon Oct 29 15:15:52 2018: Debug: authorize { (2116) Mon Oct 29 15:15:52 2018: Debug: policy filter_username { (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name) { (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name) -> TRUE (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name) { (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name =~ / /) { (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name =~ / /) -> FALSE (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) { (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name =~ /@[^@]*@/ ) -> FALSE (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name =~ /\.\./ ) { (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name =~ /\.\./ ) -> FALSE (2116) Mon Oct 29 15:15:52 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) { (2116) Mon Oct 29 15:15:52 2018: Debug: if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\.(.+)$/)) -> FALSE (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name =~ /\.$/) { (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name =~ /\.$/) -> FALSE (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name =~ /@\./) { (2116) Mon Oct 29 15:15:52 2018: Debug: if (&User-Name =~ /@\./) -> FALSE (2116) Mon Oct 29 15:15:52 2018: Debug: } # if (&User-Name) = notfound (2116) Mon Oct 29 15:15:52 2018: Debug: } # policy filter_username = notfound (2116) Mon Oct 29 15:15:52 2018: Debug: [preprocess] = ok (2116) Mon Oct 29 15:15:52 2018: Debug: [chap] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [mschap] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [digest] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: suffix: Checking for suffix after "@" (2116) Mon Oct 29 15:15:52 2018: Debug: suffix: No '@' in User-Name = "user1", looking up realm NULL (2116) Mon Oct 29 15:15:52 2018: Debug: suffix: Found realm "NULL" (2116) Mon Oct 29 15:15:52 2018: Debug: suffix: Adding Stripped-User-Name = "user1" (2116) Mon Oct 29 15:15:52 2018: Debug: suffix: Adding Realm = "NULL" (2116) Mon Oct 29 15:15:52 2018: Debug: suffix: Authentication realm is LOCAL (2116) Mon Oct 29 15:15:52 2018: Debug: [suffix] = ok (2116) Mon Oct 29 15:15:52 2018: Debug: eap: No EAP-Message, not doing EAP (2116) Mon Oct 29 15:15:52 2018: Debug: [eap] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: ldap: EXPAND (&(cn=%{%{Stripped-User-Name}:-%{User-Name}})(dialupAccess=true)) (2116) Mon Oct 29 15:15:52 2018: Debug: ldap: --> (&(cn=user1)(dialupAccess=true)) (2116) Mon Oct 29 15:15:52 2018: Debug: ldap: Performing search in "o=FHDO" with filter "(&(cn=user1)(dialupAccess=true))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: ldap: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: ldap: User object found at DN "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: ldap: Added eDirectory password (2116) Mon Oct 29 15:15:52 2018: Debug: ldap: Processing user attributes (2116) Mon Oct 29 15:15:52 2018: Debug: [ldap] = updated (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB1" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB1)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB1)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB1)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB1" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB1-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB1-np)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB1-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB1-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB1-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB2" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB2)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB2)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB2)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB2" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB2-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB2-np)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB2-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB2-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB2-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB3" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB3)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB3)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB3)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB3" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB3-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB3-np)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB3-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB3-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB3-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB4" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB4)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB4)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB4)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB4" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB4-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB4-np)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB4-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB4-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB4-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB5" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB5)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB5)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB5)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB5" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB5-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB5-np)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB5-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB5-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB5-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB8" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB8)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB8)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB8)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB8" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB8-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB8-np)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB8-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB8-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB8-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB9" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB9)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB9)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB9)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB9" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB9-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB9-np)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB9-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB9-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB9-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB10" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB10)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB10)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB10)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB10" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "FB10-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=FB10-np)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=FB10-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=FB10-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "FB10-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "idial" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=idial)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=idial)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=idial)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "idial" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "HIT-Abteilung1" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=HIT-Abteilung1)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=HIT-Abteilung1)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=HIT-Abteilung1)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Search returned no results (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking user object's groupMembership attributes (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=user1,ou=users,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=MobilityUser,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=MobilityUser,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=MobilityUser,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=MobilityUser,ou=groups,o=fhdo" resolves to name "MobilityUser" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=filr_intern,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=filr_intern,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=filr_intern,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=filr_intern,ou=groups,o=fhdo" resolves to name "filr_intern" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=DEZVI,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=DEZVI,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=DEZVI,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=DEZVI,ou=groups,o=fhdo" resolves to name "DEZVI" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Identity Mangagement,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Identity Mangagement" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Agents,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Agents,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Agents,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Agents,ou=groups,o=fhdo" resolves to name "OTRS_Agents" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Processing groupMembership value "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" as a DN (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Resolving group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" to group name (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing unfiltered search in "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo", scope "base" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Group DN "cn=OTRS_Hochschul-IT::Computer Pools,ou=groups,o=fhdo" resolves to name "OTRS_Hochschul-IT::Computer Pools" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User is not a member of "HIT-Abteilung1" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Searching for user in group "HIT-Abteilung1-np" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Using user DN from request "cn=user1,ou=users,o=fhdo" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Checking for user in group objects (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND (&(cn=HIT-Abteilung1-np)(objectClass=groupOfNames)(member=%{control:Ldap-UserDn})) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> (&(cn=HIT-Abteilung1-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo)) (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Performing search in "o=FHDO" with filter "(&(cn=HIT-Abteilung1-np)(objectClass=groupOfNames)(member=cn\3duser1\2cou\3dusers\2co\3dfhdo))", scope "sub" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: Waiting for search result... (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: User found in group object "o=FHDO" (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: users: Matched entry DEFAULT at line 60 (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: EXPAND Welcome! %{User-Name}! (2116) Mon Oct 29 15:15:52 2018: Debug: files_vpn: --> Welcome! user1! (2116) Mon Oct 29 15:15:52 2018: Debug: [files_vpn] = ok (2116) Mon Oct 29 15:15:52 2018: Debug: sql: EXPAND %{User-Name} (2116) Mon Oct 29 15:15:52 2018: Debug: sql: --> user1 (2116) Mon Oct 29 15:15:52 2018: Debug: sql: SQL-User-Name set to 'user1' (2116) Mon Oct 29 15:15:52 2018: Debug: sql: EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id (2116) Mon Oct 29 15:15:52 2018: Debug: sql: --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user1' ORDER BY id (2116) Mon Oct 29 15:15:52 2018: Debug: sql: Executing select query: SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user1' ORDER BY id (2116) Mon Oct 29 15:15:52 2018: Debug: sql: EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority (2116) Mon Oct 29 15:15:52 2018: Debug: sql: --> SELECT groupname FROM radusergroup WHERE username = 'user1' ORDER BY priority (2116) Mon Oct 29 15:15:52 2018: Debug: sql: Executing select query: SELECT groupname FROM radusergroup WHERE username = 'user1' ORDER BY priority (2116) Mon Oct 29 15:15:52 2018: Debug: sql: User not found in any groups (2116) Mon Oct 29 15:15:52 2018: Debug: [sql] = notfound (2116) Mon Oct 29 15:15:52 2018: Debug: [expiration] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [logintime] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [pap] = updated (2116) Mon Oct 29 15:15:52 2018: Debug: } # authorize = updated (2116) Mon Oct 29 15:15:52 2018: Debug: Found Auth-Type = PAP (2116) Mon Oct 29 15:15:52 2018: Debug: # Executing group from file /etc/freeradius/3.0/sites-enabled/vpn (2116) Mon Oct 29 15:15:52 2018: Debug: Auth-Type PAP { (2116) Mon Oct 29 15:15:52 2018: Debug: pap: Login attempt with password (2116) Mon Oct 29 15:15:52 2018: Debug: pap: Comparing with "known good" Cleartext-Password (2116) Mon Oct 29 15:15:52 2018: Debug: pap: User authenticated successfully (2116) Mon Oct 29 15:15:52 2018: Debug: [pap] = ok (2116) Mon Oct 29 15:15:52 2018: Debug: } # Auth-Type PAP = ok (2116) Mon Oct 29 15:15:52 2018: Debug: # Executing section post-auth from file /etc/freeradius/3.0/sites-enabled/vpn (2116) Mon Oct 29 15:15:52 2018: Debug: post-auth { (2116) Mon Oct 29 15:15:52 2018: Debug: update { (2116) Mon Oct 29 15:15:52 2018: Debug: No attributes updated (2116) Mon Oct 29 15:15:52 2018: Debug: } # update = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB1-B] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB1-S] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB2-B] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB2-S] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB3-B] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB3-S] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB4-B] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB4-S] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB5-B] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB5-S] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB8-B] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB8-S] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB9-B] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [FB9-S] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [DVZ-B] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: DVZ-S: EXPAND %{NAS-IP-Address} %{NAS-Port} (2116) Mon Oct 29 15:15:52 2018: Debug: DVZ-S: --> 193.25.18.219 202297344 (2116) Mon Oct 29 15:15:52 2018: Debug: DVZ-S: MD5 on 'key' directive maps to: 1472d1132b5b712256bb172b2401f290 (2116) Mon Oct 29 15:15:52 2018: Debug: DVZ-S: Searching for an entry for key: '1472d1132b5b712256bb172b2401f290' (2116) Mon Oct 29 15:15:52 2018: Debug: DVZ-S: Allocating ip to key: '1472d1132b5b712256bb172b2401f290' (2116) Mon Oct 29 15:15:52 2018: Debug: DVZ-S: num: 1 (2116) Mon Oct 29 15:15:52 2018: Debug: DVZ-S: Allocated ip 10.99.156.192 to client key: 1472d1132b5b712256bb172b2401f290 (2116) Mon Oct 29 15:15:52 2018: Debug: [DVZ-S] = ok (2116) Mon Oct 29 15:15:52 2018: Debug: [Sonstige-B] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [Sonstige-S] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [Bibl-B] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [Bibl-S] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [Verw-B] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [Verw-S] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [Gaeste] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: [Externe] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: sql: EXPAND .query (2116) Mon Oct 29 15:15:52 2018: Debug: sql: --> .query (2116) Mon Oct 29 15:15:52 2018: Debug: sql: Using query template 'query' (2116) Mon Oct 29 15:15:52 2018: Debug: sql: EXPAND %{User-Name} (2116) Mon Oct 29 15:15:52 2018: Debug: sql: --> user1 (2116) Mon Oct 29 15:15:52 2018: Debug: sql: SQL-User-Name set to 'user1' (2116) Mon Oct 29 15:15:52 2018: Debug: sql: EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') (2116) Mon Oct 29 15:15:52 2018: Debug: sql: --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user1', '100gc1dtbdwv=3D251', 'Access-Accept', '2018-10-29 15:15:52') (2116) Mon Oct 29 15:15:52 2018: Debug: sql: Executing query: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user1', '100gc1dtbdwv=3D251', 'Access-Accept', '2018-10-29 15:15:52') (2116) Mon Oct 29 15:15:52 2018: Debug: sql: SQL query returned: success (2116) Mon Oct 29 15:15:52 2018: Debug: sql: 1 record(s) updated (2116) Mon Oct 29 15:15:52 2018: Debug: [sql] = ok (2116) Mon Oct 29 15:15:52 2018: Debug: [exec] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: policy remove_reply_message_if_eap { (2116) Mon Oct 29 15:15:52 2018: Debug: if (&reply:EAP-Message && &reply:Reply-Message) { (2116) Mon Oct 29 15:15:52 2018: Debug: if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE (2116) Mon Oct 29 15:15:52 2018: Debug: else { (2116) Mon Oct 29 15:15:52 2018: Debug: [noop] = noop (2116) Mon Oct 29 15:15:52 2018: Debug: } # else = noop (2116) Mon Oct 29 15:15:52 2018: Debug: } # policy remove_reply_message_if_eap = noop (2116) Mon Oct 29 15:15:52 2018: Debug: } # post-auth = ok (2116) Mon Oct 29 15:15:52 2018: Debug: Sent Access-Accept Id 39 from 10.100.16.162:2001 to 193.25.18.219:48008 length 0 (2116) Mon Oct 29 15:15:52 2018: Debug: Tunnel-Type = VLAN (2116) Mon Oct 29 15:15:52 2018: Debug: Tunnel-Medium-Type = IEEE-802 (2116) Mon Oct 29 15:15:52 2018: Debug: Tunnel-Private-Group-Id = "410" (2116) Mon Oct 29 15:15:52 2018: Debug: Reply-Message = "Welcome! user1!" (2116) Mon Oct 29 15:15:52 2018: Debug: Framed-IP-Address = 10.99.156.192 (2116) Mon Oct 29 15:15:52 2018: Debug: Framed-IP-Netmask = 255.255.254.0 (2116) Mon Oct 29 15:15:52 2018: Debug: Finished request (2153) Mon Oct 29 15:15:53 2018: Debug: Received Accounting-Request Id 40 from 193.25.18.219:38622 to 10.100.16.162:2011 length 177 (2153) Mon Oct 29 15:15:53 2018: Debug: User-Name = "user1" (2153) Mon Oct 29 15:15:53 2018: Debug: NAS-Port = 202297344 (2153) Mon Oct 29 15:15:53 2018: Debug: Service-Type = Framed-User (2153) Mon Oct 29 15:15:53 2018: Debug: Framed-Protocol = PPP (2153) Mon Oct 29 15:15:53 2018: Debug: Framed-IP-Address = 10.99.156.192 (2153) Mon Oct 29 15:15:53 2018: Debug: Called-Station-Id = "193.25.18.219" (2153) Mon Oct 29 15:15:53 2018: Debug: Calling-Station-Id = "109.90.177.240" (2153) Mon Oct 29 15:15:53 2018: Debug: Acct-Status-Type = Start (2153) Mon Oct 29 15:15:53 2018: Debug: Acct-Delay-Time = 0 (2153) Mon Oct 29 15:15:53 2018: Debug: Acct-Session-Id = "6DC02E36" (2153) Mon Oct 29 15:15:53 2018: Debug: Acct-Authentic = RADIUS (2153) Mon Oct 29 15:15:53 2018: Debug: NAS-Port-Type = Virtual (2153) Mon Oct 29 15:15:53 2018: Debug: Tunnel-Client-Endpoint:0 = "109.90.177.240" (2153) Mon Oct 29 15:15:53 2018: Debug: ASA-TunnelGroupName = "xxxxxxx" (2153) Mon Oct 29 15:15:53 2018: Debug: ASA-ClientType = Cisco-VPN-Client-IKEv1 (2153) Mon Oct 29 15:15:53 2018: Debug: ASA-SessionType = Cisco-VPN-Client/IKEv1 (2153) Mon Oct 29 15:15:53 2018: Debug: NAS-IP-Address = 193.25.18.219 (2153) Mon Oct 29 15:15:53 2018: Debug: # Executing section preacct from file /etc/freeradius/3.0/sites-enabled/vpn (2153) Mon Oct 29 15:15:53 2018: Debug: preacct { (2153) Mon Oct 29 15:15:53 2018: Debug: [preprocess] = ok (2153) Mon Oct 29 15:15:53 2018: Debug: policy acct_unique { (2153) Mon Oct 29 15:15:53 2018: Debug: update request { (2153) Mon Oct 29 15:15:53 2018: Debug: } # update request = noop (2153) Mon Oct 29 15:15:53 2018: Debug: if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { (2153) Mon Oct 29 15:15:53 2018: Debug: EXPAND %{hex:&Class} (2153) Mon Oct 29 15:15:53 2018: Debug: --> (2153) Mon Oct 29 15:15:53 2018: Debug: EXPAND ^%{hex:&Tmp-String-9} (2153) Mon Oct 29 15:15:53 2018: Debug: --> ^61693a (2153) Mon Oct 29 15:15:53 2018: Debug: if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE (2153) Mon Oct 29 15:15:53 2018: Debug: else { (2153) Mon Oct 29 15:15:53 2018: Debug: update request { (2153) Mon Oct 29 15:15:53 2018: Debug: EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} (2153) Mon Oct 29 15:15:53 2018: Debug: --> 1408e9c9dc08d07a414a98a2adc014c9 (2153) Mon Oct 29 15:15:53 2018: Debug: } # update request = noop (2153) Mon Oct 29 15:15:53 2018: Debug: } # else = noop (2153) Mon Oct 29 15:15:53 2018: Debug: } # policy acct_unique = noop (2153) Mon Oct 29 15:15:53 2018: Debug: suffix: Checking for suffix after "@" (2153) Mon Oct 29 15:15:53 2018: Debug: suffix: No '@' in User-Name = "user1", looking up realm NULL (2153) Mon Oct 29 15:15:53 2018: Debug: suffix: Found realm "NULL" (2153) Mon Oct 29 15:15:53 2018: Debug: suffix: Adding Stripped-User-Name = "user1" (2153) Mon Oct 29 15:15:53 2018: Debug: suffix: Adding Realm = "NULL" (2153) Mon Oct 29 15:15:53 2018: Debug: suffix: Accounting realm is LOCAL (2153) Mon Oct 29 15:15:53 2018: Debug: [suffix] = ok (2153) Mon Oct 29 15:15:53 2018: Debug: [files] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: } # preacct = ok (2153) Mon Oct 29 15:15:53 2018: Debug: # Executing section accounting from file /etc/freeradius/3.0/sites-enabled/vpn (2153) Mon Oct 29 15:15:53 2018: Debug: accounting { (2153) Mon Oct 29 15:15:53 2018: Debug: detail: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d (2153) Mon Oct 29 15:15:53 2018: Debug: detail: --> /var/log/freeradius/radacct/193.25.18.219/detail-20181029 (2153) Mon Oct 29 15:15:53 2018: Debug: detail: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freeradius/radacct/193.25.18.219/detail-20181029 (2153) Mon Oct 29 15:15:53 2018: Debug: detail: EXPAND %t (2153) Mon Oct 29 15:15:53 2018: Debug: detail: --> Mon Oct 29 15:15:53 2018 (2153) Mon Oct 29 15:15:53 2018: Debug: [detail] = ok (2153) Mon Oct 29 15:15:53 2018: Debug: [unix] = ok (2153) Mon Oct 29 15:15:53 2018: Debug: FB1-B: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB1-B] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB1-S: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB1-S] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB2-B: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB2-B] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB2-S: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB2-S] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB3-B: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB3-B] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB3-S: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB3-S] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB4-B: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB4-B] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB4-S: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB4-S] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB5-B: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB5-B] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB5-S: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB5-S] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB8-B: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB8-B] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB8-S: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB8-S] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB9-B: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB9-B] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: FB9-S: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [FB9-S] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: DVZ-B: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [DVZ-B] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: DVZ-S: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [DVZ-S] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: Sonstige-B: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [Sonstige-B] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: Sonstige-S: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [Sonstige-S] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: Bibl-B: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [Bibl-B] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: Bibl-S: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [Bibl-S] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: Verw-B: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [Verw-B] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: Verw-S: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [Verw-S] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: Gaeste: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [Gaeste] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: Externe: This is not an Accounting-Stop (2153) Mon Oct 29 15:15:53 2018: Debug: [Externe] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: sql: EXPAND %{tolower:type.%{Acct-Status-Type}.query} (2153) Mon Oct 29 15:15:53 2018: Debug: sql: --> type.start.query (2153) Mon Oct 29 15:15:53 2018: Debug: sql: Using query template 'query' (2153) Mon Oct 29 15:15:53 2018: Debug: sql: EXPAND %{User-Name} (2153) Mon Oct 29 15:15:53 2018: Debug: sql: --> user1 (2153) Mon Oct 29 15:15:53 2018: Debug: sql: SQL-User-Name set to 'user1' (2153) Mon Oct 29 15:15:53 2018: Debug: sql: EXPAND INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{%{NAS-Port-ID}:-%{NAS-Port}}', '%{NAS-Port-Type}', FROM_UNIXTIME(%{integer:Event-Timestamp}), FROM_UNIXTIME(%{integer:Event-Timestamp}), NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}') (2153) Mon Oct 29 15:15:53 2018: Debug: sql: --> INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('6DC02E36', '1408e9c9dc08d07a414a98a2adc014c9', 'user1', 'NULL', '193.25.18.219', '202297344', 'Virtual', FROM_UNIXTIME(1540822553), FROM_UNIXTIME(1540822553), NULL, '0', 'RADIUS', '', '', '0', '0', '193.25.18.219', '109.90.177.240', '', 'Framed-User', 'PPP', '10.99.156.192') (2153) Mon Oct 29 15:15:53 2018: Debug: sql: Executing query: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctupdatetime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress) VALUES ('6DC02E36', '1408e9c9dc08d07a414a98a2adc014c9', 'user1', 'NULL', '193.25.18.219', '202297344', 'Virtual', FROM_UNIXTIME(1540822553), FROM_UNIXTIME(1540822553), NULL, '0', 'RADIUS', '', '', '0', '0', '193.25.18.219', '109.90.177.240', '', 'Framed-User', 'PPP', '10.99.156.192') (2153) Mon Oct 29 15:15:53 2018: Debug: sql: SQL query returned: success (2153) Mon Oct 29 15:15:53 2018: Debug: sql: 1 record(s) updated (2153) Mon Oct 29 15:15:53 2018: Debug: [sql] = ok (2153) Mon Oct 29 15:15:53 2018: Debug: [exec] = noop (2153) Mon Oct 29 15:15:53 2018: Debug: attr_filter.accounting_response: EXPAND %{User-Name} (2153) Mon Oct 29 15:15:53 2018: Debug: attr_filter.accounting_response: --> user1 (2153) Mon Oct 29 15:15:53 2018: Debug: attr_filter.accounting_response: Matched entry DEFAULT at line 12 (2153) Mon Oct 29 15:15:53 2018: Debug: [attr_filter.accounting_response] = updated (2153) Mon Oct 29 15:15:53 2018: Debug: } # accounting = updated (2153) Mon Oct 29 15:15:53 2018: Debug: Sent Accounting-Response Id 40 from 10.100.16.162:2011 to 193.25.18.219:38622 length 0 (2153) Mon Oct 29 15:15:53 2018: Debug: Finished request (2153) Mon Oct 29 15:15:53 2018: Debug: Cleaning up request packet ID 40 with timestamp +33 (2358) Mon Oct 29 15:15:56 2018: Debug: Received Accounting-Request Id 41 from 193.25.18.219:38622 to 10.100.16.162:2011 length 213 (2358) Mon Oct 29 15:15:56 2018: Debug: User-Name = "user1" (2358) Mon Oct 29 15:15:56 2018: Debug: NAS-Port = 202297344 (2358) Mon Oct 29 15:15:56 2018: Debug: Service-Type = Framed-User (2358) Mon Oct 29 15:15:56 2018: Debug: Framed-Protocol = PPP (2358) Mon Oct 29 15:15:56 2018: Debug: Framed-IP-Address = 10.99.156.192 (2358) Mon Oct 29 15:15:56 2018: Debug: Called-Station-Id = "193.25.18.219" (2358) Mon Oct 29 15:15:56 2018: Debug: Calling-Station-Id = "109.90.177.240" (2358) Mon Oct 29 15:15:56 2018: Debug: Acct-Status-Type = Stop (2358) Mon Oct 29 15:15:56 2018: Debug: Acct-Delay-Time = 0 (2358) Mon Oct 29 15:15:56 2018: Debug: Acct-Input-Octets = 2848 (2358) Mon Oct 29 15:15:56 2018: Debug: Acct-Output-Octets = 11655 (2358) Mon Oct 29 15:15:56 2018: Debug: Acct-Session-Id = "6DC02E36" (2358) Mon Oct 29 15:15:56 2018: Debug: Acct-Authentic = RADIUS (2358) Mon Oct 29 15:15:56 2018: Debug: Acct-Session-Time = 3 (2358) Mon Oct 29 15:15:56 2018: Debug: Acct-Input-Packets = 43 (2358) Mon Oct 29 15:15:56 2018: Debug: Acct-Output-Packets = 17 (2358) Mon Oct 29 15:15:56 2018: Debug: Acct-Terminate-Cause = User-Request (2358) Mon Oct 29 15:15:56 2018: Debug: NAS-Port-Type = Virtual (2358) Mon Oct 29 15:15:56 2018: Debug: Tunnel-Client-Endpoint:0 = "109.90.177.240" (2358) Mon Oct 29 15:15:56 2018: Debug: ASA-TunnelGroupName = "xxxxxxx" (2358) Mon Oct 29 15:15:56 2018: Debug: ASA-ClientType = Cisco-VPN-Client-IKEv1 (2358) Mon Oct 29 15:15:56 2018: Debug: ASA-SessionType = Cisco-VPN-Client/IKEv1 (2358) Mon Oct 29 15:15:56 2018: Debug: NAS-IP-Address = 193.25.18.219 (2358) Mon Oct 29 15:15:56 2018: Debug: # Executing section preacct from file /etc/freeradius/3.0/sites-enabled/vpn (2358) Mon Oct 29 15:15:56 2018: Debug: preacct { (2358) Mon Oct 29 15:15:56 2018: Debug: [preprocess] = ok (2358) Mon Oct 29 15:15:56 2018: Debug: policy acct_unique { (2358) Mon Oct 29 15:15:56 2018: Debug: update request { (2358) Mon Oct 29 15:15:56 2018: Debug: } # update request = noop (2358) Mon Oct 29 15:15:56 2018: Debug: if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) { (2358) Mon Oct 29 15:15:56 2018: Debug: EXPAND %{hex:&Class} (2358) Mon Oct 29 15:15:56 2018: Debug: --> (2358) Mon Oct 29 15:15:56 2018: Debug: EXPAND ^%{hex:&Tmp-String-9} (2358) Mon Oct 29 15:15:56 2018: Debug: --> ^61693a (2358) Mon Oct 29 15:15:56 2018: Debug: if (("%{hex:&Class}" =~ /^%{hex:&Tmp-String-9}/) && ("%{string:&Class}" =~ /^ai:([0-9a-f]{32})/i)) -> FALSE (2358) Mon Oct 29 15:15:56 2018: Debug: else { (2358) Mon Oct 29 15:15:56 2018: Debug: update request { (2358) Mon Oct 29 15:15:56 2018: Debug: EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}} (2358) Mon Oct 29 15:15:56 2018: Debug: --> 1408e9c9dc08d07a414a98a2adc014c9 (2358) Mon Oct 29 15:15:56 2018: Debug: } # update request = noop (2358) Mon Oct 29 15:15:56 2018: Debug: } # else = noop (2358) Mon Oct 29 15:15:56 2018: Debug: } # policy acct_unique = noop (2358) Mon Oct 29 15:15:56 2018: Debug: suffix: Checking for suffix after "@" (2358) Mon Oct 29 15:15:56 2018: Debug: suffix: No '@' in User-Name = "user1", looking up realm NULL (2358) Mon Oct 29 15:15:56 2018: Debug: suffix: Found realm "NULL" (2358) Mon Oct 29 15:15:56 2018: Debug: suffix: Adding Stripped-User-Name = "user1" (2358) Mon Oct 29 15:15:56 2018: Debug: suffix: Adding Realm = "NULL" (2358) Mon Oct 29 15:15:56 2018: Debug: suffix: Accounting realm is LOCAL (2358) Mon Oct 29 15:15:56 2018: Debug: [suffix] = ok (2358) Mon Oct 29 15:15:56 2018: Debug: [files] = noop (2358) Mon Oct 29 15:15:56 2018: Debug: } # preacct = ok (2358) Mon Oct 29 15:15:56 2018: Debug: # Executing section accounting from file /etc/freeradius/3.0/sites-enabled/vpn (2358) Mon Oct 29 15:15:56 2018: Debug: accounting { (2358) Mon Oct 29 15:15:56 2018: Debug: detail: EXPAND /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d (2358) Mon Oct 29 15:15:56 2018: Debug: detail: --> /var/log/freeradius/radacct/193.25.18.219/detail-20181029 (2358) Mon Oct 29 15:15:56 2018: Debug: detail: /var/log/freeradius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /var/log/freeradius/radacct/193.25.18.219/detail-20181029 (2358) Mon Oct 29 15:15:56 2018: Debug: detail: EXPAND %t (2358) Mon Oct 29 15:15:56 2018: Debug: detail: --> Mon Oct 29 15:15:56 2018 (2358) Mon Oct 29 15:15:56 2018: Debug: [detail] = ok (2358) Mon Oct 29 15:15:56 2018: Debug: [unix] = ok (2358) Mon Oct 29 15:15:56 2018: Debug: FB1-B: EXPAND %{NAS-IP-Address} %{NAS-Port} (2358) Mon Oct 29 15:15:56 2018: Debug: FB1-B: --> 193.25.18.219 202297344 (2358) Mon Oct 29 15:15:56 2018: Debug: FB1-B: MD5 on 'key' directive maps to: 1472d1132b5b712256bb172b2401f290 (2358) Mon Oct 29 15:15:56 2018: Debug: FB1-B: Searching for an entry for key: '193.25.18.219 202297344' (2358) Mon Oct 29 15:15:56 2018: Debug: FB1-B: Entry not found (2358) Mon Oct 29 15:15:56 2018: Debug: [FB1-B] = notfound (2358) Mon Oct 29 15:15:56 2018: Debug: } # accounting = notfound (2358) Mon Oct 29 15:15:56 2018: Debug: Not sending reply to client. (2358) Mon Oct 29 15:15:56 2018: Debug: Finished request (2358) Mon Oct 29 15:15:57 2018: Debug: Cleaning up request packet ID 41 with timestamp +36 (2116) Mon Oct 29 15:15:57 2018: Debug: Cleaning up request packet ID 39 with timestamp +32 (2512) Mon Oct 29 15:15:58 2018: ERROR: sql: rlm_sql_mysql: ERROR 1406 (Data too long for column 'username' at row 1): 22001 Here the configuration site-available/vpn server vpn { listen { type = auth ipaddr = * port = 2001 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { ipaddr = * port = 2011 type = acct limit { } } listen { type = auth ipv6addr = :: # any. ::1 == localhost port = 2001 limit { max_connections = 16 lifetime = 0 idle_timeout = 30 } } listen { ipv6addr = :: port = 2011 type = acct limit { } } authorize { filter_username preprocess chap mschap digest suffix eap { ok = return } ldap files_vpn -sql expiration logintime pap } authenticate { Auth-Type PAP { pap } Auth-Type CHAP { chap } Auth-Type MS-CHAP { mschap } mschap digest eap } preacct { preprocess acct_unique suffix files } accounting { detail unix FB1-B FB1-S FB2-B FB2-S FB3-B FB3-S FB4-B FB4-S FB5-B FB5-S FB8-B FB8-S FB9-B FB9-S DVZ-B DVZ-S Sonstige-B Sonstige-S Bibl-B Bibl-S Verw-B Verw-S Gaeste Externe -sql exec attr_filter.accounting_response } session { } post-auth { update { &reply: += &session-state: } FB1-B FB1-S FB2-B FB2-S FB3-B FB3-S FB4-B FB4-S FB5-B FB5-S FB8-B FB8-S FB9-B FB9-S DVZ-B DVZ-S Sonstige-B Sonstige-S Bibl-B Bibl-S Verw-B Verw-S Gaeste Externe -sql exec remove_reply_message_if_eap Post-Auth-Type REJECT { -sql attr_filter.access_reject eap remove_reply_message_if_eap } Post-Auth-Type Challenge { } } pre-proxy { } post-proxy { eap } } Example Content from ippool module ippool main_pool { filename = ${db_dir}/db.ippool range_start = 192.0.2.1 range_stop = 192.0.2.254 netmask = 255.255.255.0 cache_size = 800 ip_index = ${db_dir}/db.ipindex override = no maximum_timeout = 0 } ippool FB1-B { range_start = 10.99.1.10 range_stop = 10.99.2.254 netmask = 255.255.254.0 cache_size = 504 filename = ${db_dir}/ippool_FB1-B.db ip_index = ${db_dir}/db.ipindexFB1-B override = no maximum_timeout = 0 } ippool FB1-S { range_start = 10.99.128.10 range_stop = 10.99.129.254 netmask = 255.255.254.0 cache_size = 504 filename = ${db_dir}/ippool_FB1-S.db ip_index = ${db_dir}/db.ipindexFB1-S override = no maximum_timeout = 0 } Yours sincerely Lars Hillebrand __ Fachhochschule Dortmund University of Applied Sciences and Arts Dipl.-Ing. (FH) Lars Hillebrand Dez. VI, IT-Basisdienste Sonnenstraße 100 - 44139 Dortmund Raum SON D 008 Tel 0231 9112-9253 Fax 0231 9112-9338 lars.hillebrand@fh-dortmund.de www.fh-dortmund.de

Am 29.10.2018 um 16:30 schrieb Alan DeKok <aland@deployingradius.com>:

On Oct 29, 2018, at 10:53 AM, Lars Hillebrand <lars.hillebrand@fh-dortmund.de> wrote:

...

I have a question regarding the release of IP addresses with the module ippool. We are about to replace our old Feeradius 2.2.8 with a new 3.0.16 installation. This worked very well, but there is still a problem with the release of the IP pools after the Acct-Stop.

The corresponding "Acct-Status-Type = Stop" packets arrive correctly at the radius, but the evaluation is exited after the first "ippool area" within which no IP is found. (unabridged debug log in appendix —> debug_1)

(6079) Mon Oct 29 14:40:20 2018: Debug: User-Name = "user1"

PLEASE follow the documentation. It's not hard: http://wiki.freeradius.org/list-help

...

(6079) Mon Oct 29 14:40:20 2018: Debug: FB1-B: EXPAND %{NAS-IP-Address} %{NAS-Port} (6079) Mon Oct 29 14:40:20 2018: Debug: FB1-B: --> 193.25.18.219 202153984 (6079) Mon Oct 29 14:40:20 2018: Debug: FB1-B: MD5 on 'key' directive maps to: 8c9ebba43c49461c579616773eb1d008 (6079) Mon Oct 29 14:40:20 2018: Debug: FB1-B: Searching for an entry for key: '193.25.18.219 202153984' (6079) Mon Oct 29 14:40:20 2018: Debug: FB1-B: Entry not found (6079) Mon Oct 29 14:40:20 2018: Debug: [FB1-B] = notfound

What does that module do? Is it the IP pool module?

It's best to ask *good* questions and giving *useful* information. We can't read your mind.

...

(6079) Mon Oct 29 14:40:20 2018: Debug: } # accounting = notfound (6079) Mon Oct 29 14:40:20 2018: Debug: Not sending reply to client. (6079) Mon Oct 29 14:40:20 2018: Debug: Finished request (6079) Mon Oct 29 14:40:21 2018: Debug: Cleaning up request packet ID 132 with timestamp +76

If we adjust the order of the ippools in the site-availiable configuration so that the used area is in first place,

What's the "used area"? Please don't invent your own vocabulary when asking questions. That makes it harder to help you.

...

it will be evaluated correctly at the Acct-Stop and the IP address will be released but the evaluation will jump out again after the first pool without an entry.

What does that mean?

...

Does anyone know a similar behavior and has a tip for us?

Follow the documentation. It will work.

If the IP pool module is returning "not found", then it's because the IP entry was not found.

You can use the "rlm_ippool_tool" module to query the IP pool database. See "man rlm_ippool_tool"

...

The unabridged debug logs and the corresponding sites-available configuration (vpn) can be found in the appendix.

The mailing list strips most attachments. Please just post the relevant debug output inline.

Alan DeKok.

- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html