LDAP slow initial Sync

Infos:

  • Used Zammad version: 5.1.1-1650894976.28c5b986.bullseye
  • Used Zammad installation type: package
  • Operating system: Debian 11 (bullseye)
  • Browser + version: firefox.x86_64 91.7.0-3.el7.centos
  • Used MySQL version: 10.5.15-MariaDB-0+deb11u1
  • Used LDAP version: OpenLDAP 2.4.57+dfsg-3 (same version on zammad machine & remote server)

Expected behavior:

  • Initial LDAP sync completes in less than a few hours.

Actual behavior:

  • Initial LDAP sync takes >=20 hours.

Steps to reproduce the behavior:

  • Migrate Zammad (this required the recommended approach of doing major version updates and executing some rake commands but works!)
    • from source installation v3.3 on CentOS7 with accounts created via generic OAuth (and possibly other methods)
    • to package installation v5.1 on Debian11
  • Perform an initial LDAP sync on a system with ~9500 existing accounts and ~1500 accounts residing in LDAP (most of the LDAP accounts should match to existing zammad accounts).

System Specs (Test Environment):

  • 8 VCPUs
  • 16 GiB RAM
  • no swap (ruling out swap related issues)
  • qemu libvirt guest with a non-sparse qcow2 image as backing device (cache=writethrough)

Configurations & Logs:

  • Zammad
irb(main):001:0> ImportJob.last.attributes.except('payload').inspect
=> "{\"id\"=>15,
     \"name\"=>\"Import::Ldap\",
     \"dry_run\"=>false,
     \"result\"=>{
        \"skipped\"=>0,
        \"created\"=>163,
        \"updated\"=>1327,
        \"unchanged\"=>0,
        \"failed\"=>0,
        \"deactivated\"=>0,
        \"sum\"=>1490,
        \"total\"=>1565
     },
     \"started_at\"=>Thu, 28 Apr 2022 18:21:31 UTC +00:00,
     \"finished_at\"=>nil,
     \"created_at\"=>Thu, 28 Apr 2022 18:21:31 UTC +00:00,
     \"updated_at\"=>Fri, 29 Apr 2022 08:49:42 UTC +00:00
    }"

I tried increasing zammad’s performance with confiugration tips that i found on this forum:

$ zammad config:set ZAMMAD_SESSION_JOBS_CONCURRENT=4        # i didn't notice any difference
$ zammad config:set WEB_CONCURRENCY=4                       # i think the Webgui got a lot faster, but it had no impact on the LDAP Sync
$ zammad config:set MAX_THREADS=32                          # no difference (only 2 more than default afterall)
$ zammad config:set MIN_THREADS=8                           # no difference (only 3 more than default afterall)

$ mount -t tmpfs -o size=1g tmpfs /opt/zammad/tmp           # only 55M used 16h into the LDAP Sync
  • LDAP

Probably worth mentioning is that the LDAP Server uses the uncommon sql backend.
But the DIT design is incredibly simple and queriying & authentication works as expected from the zammad server.

dn: uid=<uid>,dc=<organization>,dc=com
objectClass: inetOrgPerson
cn: <firstname> <lastname>
sn: <lastname>
uid: <uid>
mail: <email>
givenName: <firstname>
userPassword:: <base64-encoded|PBKDF2-Password-Hash>

The corresponding logs from slapd. Timestamps of slapd are in UTC +0200 (so 20:21:31 corresponds to the ImportJob started at 18:21:31)

Apr 28 20:16:14 support-test systemd[1]: Starting LSB: OpenLDAP standalone server (Lightweight Directory Access Protocol)...
Apr 28 20:16:14 support-test slapd[167961]: @(#) $OpenLDAP: slapd 2.4.57+dfsg-3 (May 15 2021 23:03:34) $
                                                    Debian OpenLDAP Maintainers <pkg-openldap-devel@lists.alioth.debian.org>
Apr 28 20:16:14 support-test slapd[167962]: slapd starting
Apr 28 20:16:14 support-test slapd[167956]: Starting OpenLDAP: slapd.
Apr 28 20:16:14 support-test systemd[1]: Started LSB: OpenLDAP standalone server (Lightweight Directory Access Protocol).
Apr 28 20:21:13 support-test slapd[167962]: conn=1000 fd=11 ACCEPT from IP=192.168.122.225:43702 (IP=0.0.0.0:389)
Apr 28 20:21:13 support-test slapd[167962]: conn=1000 op=0 BIND dn="uid=1340,dc=<organization>,dc=com" method=128
Apr 28 20:21:13 support-test slapd[167962]: conn=1000 op=0 BIND dn="uid=1340,dc=<organization>,dc=com" mech=SIMPLE ssf=0
Apr 28 20:21:13 support-test slapd[167962]: conn=1000 op=0 RESULT tag=97 err=0 text=
Apr 28 20:21:13 support-test slapd[167962]: conn=1000 op=1 EXT oid=1.3.6.1.4.1.4203.1.11.3
Apr 28 20:21:13 support-test slapd[167962]: conn=1000 op=1 WHOAMI
Apr 28 20:21:13 support-test slapd[167962]: conn=1000 op=1 RESULT oid= err=0 text=
Apr 28 20:21:13 support-test slapd[167962]: conn=1000 op=2 UNBIND
Apr 28 20:21:13 support-test slapd[167962]: conn=1000 fd=11 closed
Apr 28 20:21:31 support-test slapd[167962]: conn=1001 fd=11 ACCEPT from IP=192.168.122.225:43704 (IP=0.0.0.0:389)
Apr 28 20:21:31 support-test slapd[167962]: conn=1001 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" method=128
Apr 28 20:21:31 support-test slapd[167962]: conn=1001 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" mech=SIMPLE ssf=0
Apr 28 20:21:31 support-test slapd[167962]: conn=1001 op=0 RESULT tag=97 err=0 text=
Apr 28 20:21:31 support-test slapd[167962]: conn=1001 fd=11 closed (connection lost)
Apr 28 20:21:31 support-test slapd[167962]: conn=1002 fd=11 ACCEPT from IP=192.168.122.225:43706 (IP=0.0.0.0:389)
Apr 28 20:21:31 support-test slapd[167962]: conn=1002 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" method=128
Apr 28 20:21:31 support-test slapd[167962]: conn=1002 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" mech=SIMPLE ssf=0
Apr 28 20:21:31 support-test slapd[167962]: conn=1002 op=0 RESULT tag=97 err=0 text=
Apr 28 20:21:31 support-test slapd[167962]: conn=1002 op=1 SRCH base="" scope=0 deref=0 filter="(objectClass=*)"
Apr 28 20:21:31 support-test slapd[167962]: conn=1002 op=1 SRCH attr=altServer namingContexts supportedCapabilities supportedControl supportedExtension supportedFeatures supportedLdapVersion supportedSASLMechanisms
Apr 28 20:21:31 support-test slapd[167962]: conn=1002 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text=
Apr 28 20:21:31 support-test slapd[167962]: conn=1002 fd=11 closed (connection lost)
Apr 28 20:21:31 support-test slapd[167962]: conn=1003 fd=11 ACCEPT from IP=192.168.122.225:43708 (IP=0.0.0.0:389)
Apr 28 20:21:31 support-test slapd[167962]: conn=1003 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" method=128
Apr 28 20:21:31 support-test slapd[167962]: conn=1003 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" mech=SIMPLE ssf=0
Apr 28 20:21:31 support-test slapd[167962]: conn=1003 op=0 RESULT tag=97 err=0 text=
Apr 28 20:21:31 support-test slapd[167962]: conn=1003 op=1 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=organization)"
Apr 28 20:21:31 support-test slapd[167962]: conn=1003 op=1 SRCH attr=dn member memberuid uniquemember
Apr 28 20:21:31 support-test slapd[167962]: conn=1003 op=1 SEARCH RESULT tag=101 err=0 nentries=1 text=
Apr 28 20:21:31 support-test slapd[167962]: conn=1003 fd=11 closed (connection lost)
Apr 28 20:21:31 support-test slapd[167962]: conn=1004 fd=11 ACCEPT from IP=192.168.122.225:43710 (IP=0.0.0.0:389)
Apr 28 20:21:31 support-test slapd[167962]: conn=1004 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" method=128
Apr 28 20:21:31 support-test slapd[167962]: conn=1004 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" mech=SIMPLE ssf=0
Apr 28 20:21:31 support-test slapd[167962]: conn=1004 op=0 RESULT tag=97 err=0 text=
Apr 28 20:21:31 support-test slapd[167962]: conn=1004 op=1 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:31 support-test slapd[167962]: conn=1004 op=1 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:31 support-test slapd[167962]: conn=1004 op=2 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:31 support-test slapd[167962]: conn=1004 op=2 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:31 support-test slapd[167962]: conn=1004 op=3 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:31 support-test slapd[167962]: conn=1004 op=3 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:31 support-test slapd[167962]: conn=1004 op=4 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:32 support-test slapd[167962]: conn=1004 op=4 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:32 support-test slapd[167962]: conn=1004 op=5 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:32 support-test slapd[167962]: conn=1004 op=5 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:32 support-test slapd[167962]: conn=1004 op=6 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:32 support-test slapd[167962]: conn=1004 op=6 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:32 support-test slapd[167962]: conn=1004 op=7 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:32 support-test slapd[167962]: conn=1004 op=7 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:32 support-test slapd[167962]: conn=1004 op=7 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:32 support-test slapd[167962]: conn=1004 op=8 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:32 support-test slapd[167962]: conn=1004 op=8 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:32 support-test slapd[167962]: conn=1004 op=9 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:33 support-test slapd[167962]: conn=1004 op=9 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:33 support-test slapd[167962]: conn=1004 op=10 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:33 support-test slapd[167962]: conn=1004 op=10 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:33 support-test slapd[167962]: conn=1004 op=11 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:33 support-test slapd[167962]: conn=1004 op=11 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:33 support-test slapd[167962]: conn=1004 op=12 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:33 support-test slapd[167962]: conn=1004 op=12 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:33 support-test slapd[167962]: conn=1004 op=13 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:33 support-test slapd[167962]: conn=1004 op=13 SEARCH RESULT tag=101 err=0 nentries=53 text=
Apr 28 20:21:33 support-test slapd[167962]: conn=1004 fd=11 closed (connection lost)
Apr 28 20:21:33 support-test slapd[167962]: conn=1005 fd=11 ACCEPT from IP=192.168.122.225:43712 (IP=0.0.0.0:389)
Apr 28 20:21:33 support-test slapd[167962]: conn=1005 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" method=128
Apr 28 20:21:33 support-test slapd[167962]: conn=1005 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" mech=SIMPLE ssf=0
Apr 28 20:21:33 support-test slapd[167962]: conn=1005 op=0 RESULT tag=97 err=0 text=
Apr 28 20:21:33 support-test slapd[167962]: conn=1005 op=1 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:33 support-test slapd[167962]: conn=1005 op=1 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 28 20:21:34 support-test slapd[167962]: conn=1005 op=1 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:37 support-test slapd[167962]: conn=1005 op=2 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:37 support-test slapd[167962]: conn=1005 op=2 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 28 20:21:37 support-test slapd[167962]: conn=1005 op=2 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:42 support-test slapd[167962]: conn=1005 op=3 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:42 support-test slapd[167962]: conn=1005 op=3 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 28 20:21:42 support-test slapd[167962]: conn=1005 op=3 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:48 support-test slapd[167962]: conn=1005 op=4 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:48 support-test slapd[167962]: conn=1005 op=4 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 28 20:21:48 support-test slapd[167962]: conn=1005 op=4 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:53 support-test slapd[167962]: conn=1005 op=5 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:53 support-test slapd[167962]: conn=1005 op=5 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 28 20:21:53 support-test slapd[167962]: conn=1005 op=5 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:21:59 support-test slapd[167962]: conn=1005 op=6 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:21:59 support-test slapd[167962]: conn=1005 op=6 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 28 20:21:59 support-test slapd[167962]: conn=1005 op=6 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:22:05 support-test slapd[167962]: conn=1005 op=7 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:22:05 support-test slapd[167962]: conn=1005 op=7 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 28 20:22:05 support-test slapd[167962]: conn=1005 op=7 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:22:12 support-test slapd[167962]: conn=1005 op=8 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:22:12 support-test slapd[167962]: conn=1005 op=8 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 28 20:22:12 support-test slapd[167962]: conn=1005 op=8 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:22:18 support-test slapd[167962]: conn=1005 op=9 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:22:18 support-test slapd[167962]: conn=1005 op=9 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 28 20:22:18 support-test slapd[167962]: conn=1005 op=9 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:22:24 support-test slapd[167962]: conn=1005 op=10 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:22:24 support-test slapd[167962]: conn=1005 op=10 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 28 20:22:24 support-test slapd[167962]: conn=1005 op=10 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 28 20:22:30 support-test slapd[167962]: conn=1005 op=11 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 28 20:22:30 support-test slapd[167962]: conn=1005 op=11 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 28 20:22:30 support-test slapd[167962]: conn=1005 op=11 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 29 03:49:22 support-test slapd[167962]: conn=1005 op=12 SRCH base="dc=<organization>,dc=com" scope=2 deref=0 filter="(objectClass=person)"
Apr 29 03:49:22 support-test slapd[167962]: conn=1005 op=12 SRCH attr=givenname sn mail telephonenumber dn uid
Apr 29 03:49:23 support-test slapd[167962]: conn=1005 op=12 SEARCH RESULT tag=101 err=0 nentries=126 text=
Apr 29 11:57:03 support-test slapd[167962]: conn=1006 fd=14 ACCEPT from IP=192.168.122.225:54728 (IP=0.0.0.0:389)                                       # this corresponds to a manual ldapsearch => fails
Apr 29 11:57:03 support-test slapd[167962]: conn=1006 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" method=128
Apr 29 11:57:03 support-test slapd[167962]: conn=1006 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" mech=SIMPLE ssf=0
Apr 29 11:57:03 support-test slapd[167962]: conn=1006 op=0 RESULT tag=97 err=0 text=
Apr 29 11:57:03 support-test slapd[167962]: conn=1006 op=1 SRCH base="dc=<organization>,dc=com" scope=1 deref=0 filter="(objectClass=*)"
Apr 29 11:57:03 support-test slapd[167962]: conn=1006 op=1 SEARCH RESULT tag=101 err=80 nentries=0 text=
Apr 29 11:57:03 support-test slapd[167962]: conn=1006 op=2 UNBIND
Apr 29 11:57:03 support-test slapd[167962]: conn=1006 fd=14 closed
Apr 29 11:59:24 support-test systemd[1]: Stopping LSB: OpenLDAP standalone server (Lightweight Directory Access Protocol)...                            # restarting slapd
Apr 29 11:59:24 support-test slapd[167962]: daemon: shutdown requested and initiated.
Apr 29 11:59:24 support-test slapd[167962]: conn=1005 fd=11 closed (slapd shutdown)
Apr 29 11:59:24 support-test slapd[167962]: slapd shutdown: waiting for 0 operations/tasks to finish
Apr 29 11:59:24 support-test slapd[167962]: DIGEST-MD5 common mech free
Apr 29 11:59:24 support-test slapd[167962]: DIGEST-MD5 common mech free
Apr 29 11:59:24 support-test slapd[167962]: slapd stopped.
Apr 29 11:59:24 support-test slapd[172203]: Stopping OpenLDAP: slapd.
Apr 29 11:59:24 support-test systemd[1]: slapd.service: Succeeded.
Apr 29 11:59:24 support-test systemd[1]: Stopped LSB: OpenLDAP standalone server (Lightweight Directory Access Protocol).
Apr 29 11:59:24 support-test systemd[1]: slapd.service: Consumed 1.901s CPU time.
Apr 29 11:59:24 support-test systemd[1]: Starting LSB: OpenLDAP standalone server (Lightweight Directory Access Protocol)...
Apr 29 11:59:24 support-test slapd[172213]: @(#) $OpenLDAP: slapd 2.4.57+dfsg-3 (May 15 2021 23:03:34) $
                                                    Debian OpenLDAP Maintainers <pkg-openldap-devel@lists.alioth.debian.org>
Apr 29 11:59:24 support-test slapd[172214]: slapd starting
Apr 29 11:59:24 support-test slapd[172208]: Starting OpenLDAP: slapd.
Apr 29 11:59:24 support-test systemd[1]: Started LSB: OpenLDAP standalone server (Lightweight Directory Access Protocol).
Apr 29 11:59:28 support-test slapd[172214]: conn=1000 fd=11 ACCEPT from IP=192.168.122.225:54786 (IP=0.0.0.0:389)                                       # repeating the manual ldapsearch => succeeds
Apr 29 11:59:28 support-test slapd[172214]: conn=1000 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" method=128
Apr 29 11:59:28 support-test slapd[172214]: conn=1000 op=0 BIND dn="cn=Manager,dc=<organization>,dc=com" mech=SIMPLE ssf=0
Apr 29 11:59:28 support-test slapd[172214]: conn=1000 op=0 RESULT tag=97 err=0 text=
Apr 29 11:59:28 support-test slapd[172214]: conn=1000 op=1 SRCH base="dc=<organization>,dc=com" scope=1 deref=0 filter="(objectClass=*)"
Apr 29 11:59:30 support-test slapd[172214]: conn=1000 op=1 SEARCH RESULT tag=101 err=0 nentries=1565 text=
Apr 29 11:59:30 support-test slapd[172214]: conn=1000 op=2 UNBIND
Apr 29 11:59:30 support-test slapd[172214]: conn=1000 fd=11 closed
  • MariaDB

htop shows 2 mariadb threads running on 100% CPU the whole time. ps’s output looks different but my point is, that zammad seems to be using 1 mysql connection which maxes out 1 VCPU while 7 VCPUs are almost idle and multiple available mariadb threads are sleeping. I understand that multi-threading with mariadb is generally not a simple topic and changing it can have a negative performance impact during normal operation (as opposed to thousands of INSERTs like here).

root@tickets-test:~# ps -u mysql um
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
mysql      22192 73.1 10.3 15732848 1702648 ?    -    Apr27 1875:44 /usr/sbin/mariadbd
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:00 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:28 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:00 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:00 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:00 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:00 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:00 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:10 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:07 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:31 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:14 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:01 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:00 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:00 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:41 -
mysql          - 36.1    -      -     - -        Rsl  Apr27 925:04 -
mysql          -  0.0    -      -     - -        Ssl  Apr27   0:25 -
mysql          -  0.0    -      -     - -        Ssl  Apr28   0:00 -
mysql          -  0.0    -      -     - -        Ssl  Apr28   0:04 -
mysql          -  0.0    -      -     - -        Ssl  Apr28   0:11 -
mysql          -  0.0    -      -     - -        Ssl  Apr28   0:00 -
mysql          -  0.0    -      -     - -        Ssl  01:04   0:00 -
mysql          -  0.0    -      -     - -        Ssl  10:23   0:00 -
mysql          -  0.0    -      -     - -        Ssl  10:52   0:00 -
mysql          -  0.0    -      -     - -        Ssl  10:52   0:00 -
mysql          -  0.0    -      -     - -        Ssl  10:53   0:00 -
mysql          -  0.0    -      -     - -        Ssl  11:42   0:00 -
mysql          -  0.0    -      -     - -        Ssl  11:42   0:00 -
mysql          -  0.0    -      -     - -        Ssl  11:44   0:00 -
mysql          -  0.0    -      -     - -        Ssl  11:44   0:00 -
mysql          -  0.0    -      -     - -        Ssl  11:44   0:00 -
mysql          -  0.0    -      -     - -        Ssl  11:44   0:00 -
mysql          -  0.0    -      -     - -        Ssl  11:46   0:00 -
mysql          -  0.0    -      -     - -        Ssl  11:46   0:00 -
mysql          -  0.0    -      -     - -        Ssl  11:46   0:00 -
root@tickets-test:~# mysqladmin proc stat
+------+--------+-----------+--------+---------+-------+--------------+------------------------------------------------------------------------------------------------------+----------+
| Id   | User   | Host      | db     | Command | Time  | State        | Info                                                                                                 | Progress |
+------+--------+-----------+--------+---------+-------+--------------+------------------------------------------------------------------------------------------------------+----------+
| 6172 | zammad | localhost | zammad | Sleep   | 9     |              |                                                                                                      | 0.000    |
| 6173 | zammad | localhost | zammad | Sleep   | 7     |              |                                                                                                      | 0.000    |
| 6175 | zammad | localhost | zammad | Sleep   | 1     |              |                                                                                                      | 0.000    |
| 6176 | zammad | localhost | zammad | Sleep   | 52751 |              |                                                                                                      | 0.000    |
| 6177 | zammad | localhost | zammad | Sleep   | 12    |              |                                                                                                      | 0.000    |
| 6178 | zammad | localhost | zammad | Sleep   | 23440 |              |                                                                                                      | 0.000    |
| 6183 | zammad | localhost | zammad | Sleep   | 4627  |              |                                                                                                      | 0.000    |
| 6187 | zammad | localhost | zammad | Sleep   | 39    |              |                                                                                                      | 0.000    |
| 6188 | root   | localhost | zammad | Query   | 38    | Sending data | INSERT INTO authorizations (provider, uid, username, user_id, created_at, updated_at) select distinc | 0.000    |
| 6189 | zammad | localhost | zammad | Sleep   | 52523 |              |                                                                                                      | 0.000    |
| 6190 | zammad | localhost | zammad | Sleep   | 238   |              |                                                                                                      | 0.000    |
| 6192 | zammad | localhost | zammad | Sleep   | 34    |              |                                                                                                      | 0.000    |
| 6230 | zammad | localhost | zammad | Sleep   | 1     |              |                                                                                                      | 0.000    |
| 6245 | zammad | localhost | zammad | Sleep   | 27583 |              |                                                                                                      | 0.000    |
| 7006 | zammad | localhost |        | Sleep   | 287   |              |                                                                                                      | 0.000    |
| 7008 | zammad | localhost | zammad | Sleep   | 278   |              |                                                                                                      | 0.000    |
| 7013 | zammad | localhost | zammad | Sleep   | 44    |              |                                                                                                      | 0.000    |
| 7014 | root   | localhost |        | Query   | 0     | starting     | show processlist                                                                                     | 0.000    |
+------+--------+-----------+--------+---------+-------+--------------+------------------------------------------------------------------------------------------------------+----------+
Uptime: 150790  Threads: 19  Questions: 3435002  Slow queries: 796  Opens: 184  Open tables: 177  Queries per second avg: 22.780

“Queries per second avg” starts at around 500 and then gradually decreases.
“Slow queries” start to show up after the first ~30min of the initial LDAP sync.
The “INSERT INTO authorizations …” statement only takes <=2seconds in the beginning and gradually icreases (38 seconds in this excerpt).

#---/etc/mysql/conf.d/zammad.cnf---
[client]
default_character_set = utf8

[mysql]
default_character_set = utf8

[mysqld]
collation_server = utf8_bin
init_connect = 'SET NAMES utf8'
character_set_server = utf8
max_allowed_packet = 128M

innodb_buffer_pool_size = 11GiB                                 # i tried to give mariadb as much RAM as possible
innodb_flush_log_at_trx_commit = 2                              # this is supposed to speed up flushing to disk at the expense of possible dataloss when an outage occurs
innodb_flush_method = O_DIRECT

I also enabled the mariadb query log once to check wether mariadb is just waiting for input from ldap, but that was not the case.
There are plenty of queries being executed.


This is all in a sandboxed testenvironment btw.
It feels like the mariadb is the bottleneck but i’m running out of ideas.
Any help or suggestions are welcome =) Thanks!

My proposed Workaround:

To keep the downtime of our zammad instance at a minimum for the migration i am pursuing the following approach:

  • Performing migration & updates in a sandboxed environment while keeping the production zammad instance available to the public
  • Performing initial LDAP Sync also in the sandboxed environment
  • Extracting the zammad.users & zammad.authorizations tables from the MariaDB of the now up-to-date and synced zammad instance
  • Starting the actual downtime for our zammad instance
  • Performing migration & updates again on the actual target machine
  • Applying the previously extracted mysqldumps of zammad.users & zammad.authorizations tables on the target machine’s MariaDB
  • Performing a LDAP Sync (this time its rather fast, i tested that)
  • Ending the downtime

My question concerning this workaround is “What could possibly go wrong?” =)
E.g. does an LDAP Import Job write to any other of zammad’s MySQL tables which would now be missing important entries?

Kind regards,
Julian

I am still wondering about the huge amount of time it takes to sync the accounts.
Since most of the time is spent on writing entries to the authorizations table, i took a closer look at it after a completed sync.

MariaDB [zammad]> select provider,COUNT(provider) from authorizations GROUP BY provider;
+----------+-----------------+
| provider | COUNT(provider) |
+----------+-----------------+
| oauth2   |          554692 |
+----------+-----------------+

First thing that catches my eye is, why is the auth-provider always “oauth2”?
Second question is, why are there so many entries? The users table only has 10629 rows.

Some more analysis of the authorizations table contents:

There are many unique entries in the authorizations table.

MariaDB [zammad]> select COUNT(*) from (select COUNT(uid) as number_of_duplicate_uids from authorizations GROUP BY uid) sub GROUP BY number_of_duplicate_uids HAVING number_of_duplicate_uids = 1;
+----------+
| COUNT(*) |
+----------+
|     9621 |
+----------+

But most of the entries are duplicates in the hundreds. Its not just the uid that is duplicated in those entries its every column except the entry id. Even the ‘created_at’ and ‘updated_at’ timestamps. ‘token’ and ‘secret’ seem to be always NULL. ‘username’ seems to be always empty.

MariaDB [zammad]> select COUNT(uid) from authorizations GROUP BY uid HAVING COUNT(uid) > 1 limit 10;
+------------+
| COUNT(uid) |
+------------+
|       2961 |
|      10154 |
|       5148 |
|        425 |
|        159 |
|        835 |
|        814 |
|        586 |
|        666 |
|        758 |
+------------+

Why does this happen?
Do i maybe need to configure role/group memberships in LDAP which i currently do not do?

Please help :slight_smile:
(my earlier proposed workaround is kind of flakey and would either way introduce many what seems to be redundant entries in the zammad db).

Kind regards,
Julian

I think i solved it.

The “mail” attribute of LDAP users was not being mapped to the “email” field of zammad users because the “mail” attribute was already in use for the “login” field.
Without an email address associated to a zammad user the mysql statement “INSERT INTO authorizations (provider, uid, username, user_id, created_at, updated_at) select distinc […]” probably can not find a match and produces the aforementioned duplicate entries.
The larger that table gets the longer it takes to cycle through it, resulting in the amounting slow queries.

It did take me quite a while to realize that, because in fact i did map the LDAP “mail” attribute to the zammad “email” field.
My LDAP mapping looked like that:

mail            => login
givenname       => firstname
sn              => lastname
mail            => email
telephoneNumber => phone

And i never noticed that the mapping “mail => email” gets silently dropped when pressing the save button for the configuration on the LDAP integrations page in favour of the “mail => login” mapping.

irb(main):001:0> Setting.get('ldap_config') 
=> {
     "host_url"=>"ldap://192.168.122.224",
     "options"=>{
       "dc=organization,dc=com"=>"dc=organization,dc=com"
     },
     "option"=>"dc=organization,dc=com",
     "base_dn"=>"dc=organization,dc=com",
     "bind_user"=>"cn=Manager,dc=organization,dc=com",
     "bind_pw"=>"supersecretpassword",
     "wizardData"=>{
       "backend_user_attributes"=>{
         "dn"=>"dn (e.g., uid=1,dc=organization,dc=com)",
         "cn"=>"cn (e.g., Admin )",
         "sn"=>"sn (e.g., Mustermann)",
         "uid"=>"uid (e.g., 1)",
         "mail"=>"mail (e.g., admin)",
         "givenname"=>"givenname (e.g., Admin)",
         "userpassword"=>"userpassword (e.g., {PBKDF2-SHA512}30000$salt$hash)"
       },
       "backend_groups"=>{
         "dc=organization,dc=com"=>"dc=organization,dc=com"
       },
       "user_attributes"=>{
         "login"=>"Login",
         "firstname"=>"First name",
         "lastname"=>"Last name",
         "email"=>"Email",
         "web"=>"Web",
         "phone"=>"Phone",
         "mobile"=>"Mobile",
         "fax"=>"Fax",
         "department"=>"Department",
         "address"=>"Address",
         "note"=>"Note"
       },
       "roles"=>{
         "1"=>"Admin",
         "2"=>"Agent",
         "3"=>"Customer"
       }
     },
     "user_uid"=>"uid",
     "user_filter"=>"(objectClass=person)",
     "group_uid"=>"dn",
     "group_filter"=>"(objectClass=organization)",
     "user_attributes"=>{
       "givenname"=>"firstname",
       "sn"=>"lastname",
       "mail"=>"login",
       "telephoneNumber"=>"phone"
     },
     "group_role_map"=>{},
     "unassigned_users"=>"sigup_roles"
   }

Apparently it is not possible to map one LDAP attribute to multiple zammad fields as already observed in this thread:

Solution:

I introduced a new attribute in the LDAP server “displayName” (from InetOrgPerson Schema) to hold the same value as the “mail” attribute and mapped that attribute to zammads “login” field.
This way i can map the email to both “login” & “email” and everything works as expected.

irb(main):001:0> Setting.get('ldap_config') 
=> {
     "host_url"=>"ldap://192.168.122.224",
     "options"=>{
       "dc=organization,dc=com"=>"dc=organization,dc=com"
     },
     "option"=>"dc=organization,dc=com",
     "base_dn"=>"dc=organization,dc=com",
     "bind_user"=>"cn=Manager,dc=organization,dc=com",
     "bind_pw"=>"supersecretpassword",
     "wizardData"=>{
       "backend_user_attributes"=>{
         "dn"=>"dn (e.g., uid=1,dc=organization,dc=com)",
         "cn"=>"cn (e.g., Admin )",
         "sn"=>"sn (e.g., Mustermann)",
         "uid"=>"uid (e.g., 1)",
         "mail"=>"mail (e.g., admin)",
         "givenname"=>"givenname (e.g., Admin)",
         "displayname"=>"displayname (e.g., admin)",
         "userpassword"=>"userpassword (e.g., {PBKDF2-SHA512}30000$salt$hash)"
       },
       "backend_groups"=>{
         "dc=organization,dc=com"=>"dc=organization,dc=com"
       },
       "user_attributes"=>{
         "login"=>"Login",
         "firstname"=>"First name",
         "lastname"=>"Last name",
         "email"=>"Email",
         "web"=>"Web",
         "phone"=>"Phone",
         "mobile"=>"Mobile",
         "fax"=>"Fax",
         "department"=>"Department",
         "address"=>"Address",
         "note"=>"Note"
       },
       "roles"=>{
         "1"=>"Admin",
         "2"=>"Agent",
         "3"=>"Customer"
       }
     },
     "user_uid"=>"uid",
     "user_filter"=>"(objectClass=person)",
     "group_uid"=>"dn",
     "group_filter"=>"(objectClass=organization)",
     "user_attributes"=>{
       "displayname"=>"login",
       "givenname"=>"firstname",
       "sn"=>"lastname",
       "mail"=>"email",
       "telephoneNumber"=>"phone"
     },
     "group_role_map"=>{},
     "unassigned_users"=>"sigup_roles"
   }

The resulting number of entries in the authorizations table is by a factor ~10 smaller and there are almost no duplicate entries anymore.

MariaDB [zammad]> select COUNT(*) from authorizations;
+----------+
| COUNT(*) |
+----------+
|    59221 |
+----------+

The initial Sync after enabling the LDAP integration completed in ~10min. Every subsequent Sync takes less than a few seconds.

Feature Request:

A warning message in the LDAP integration configuration dialog would be nice to notify the admin that mapping the same attribute to multiple zammad user fields is not possible.
Or preferably make it possible so that one can map LDAP attributes to multiple fields :slight_smile:

I hope this helps.

Best regards,
Julian

1 Like

Please post feature requests here:

We cannot take feature request being burried somewhere in other thread types into account.

Done :slight_smile:

This topic was automatically closed 120 days after the last reply. New replies are no longer allowed.