Uploaded image for project: 'Crowd Data Center'
  1. Crowd Data Center
  2. CWD-3044

Reduce logging during directory synchronization

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: Medium Medium
    • 2.6.1
    • 2.4.3
    • None
    • None

    • v4.3-SNAPSHOT#611-r141832

      Its looks like it is crowd embedded that actually does this. It looks like the logging is proportional to the number of groups. We don't need this much detail in the logs it will blow their size out of large LDAP directories. Admins of JIRA really don't care about these details. If they need to DEBUG performance problems then they should enable debugging rather than having it on by default. We should

      1. Get Crowd Embedded to drop these messages to DEBUG.

      We can (should?) keep around the "synchronisation" started and "synchronisation" finished logs when we fix this.

      For example, here is a sync with a small directory of ~ 10 users and ~ 5 groups.

      2011-02-09 12:17:53,308 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectory] full synchronisation for directory [ 10001 ] starting
2011-02-09 12:17:53,327 QuartzWorker-0 INFO ServiceRunner     [directory.ldap.cache.RemoteDirectoryCacheRefresher] found [ 4 ] remote users in [ 19ms ]
2011-02-09 12:17:53,328 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.j] scanning [ 4 ] users to add or update
2011-02-09 12:17:53,328 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 4 ] users for update in DB cache in [ 1ms ]
2011-02-09 12:17:53,328 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] synchronised [ 4 ] users in [ 1ms ]
2011-02-09 12:17:53,329 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 4 ] users for delete in DB cache in [ 1ms ]
2011-02-09 12:17:53,329 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned for deleted users in [ 1ms ]
2011-02-09 12:17:53,347 QuartzWorker-0 INFO ServiceRunner     [directory.ldap.cache.RemoteDirectoryCacheRefresher] found [ 4 ] remote groups in [ 18ms ]
2011-02-09 12:17:53,347 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanning [ 4 ] groups to add or update
2011-02-09 12:17:53,348 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 4 ] groups for update in DB cache in [ 1ms ]
2011-02-09 12:17:53,348 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] synchronized [ 4 ] groups in [ 1ms ]
2011-02-09 12:17:53,348 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 4 ] groups for delete in DB cache in [ 0ms ]
2011-02-09 12:17:53,384 QuartzWorker-0 INFO ServiceRunner     [directory.ldap.cache.AbstractCacheRefresher] found [ 2 ] remote user-group memberships in [ 36ms ]
2011-02-09 12:17:53,384 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 2 ] user members from [ jira-users-xx ] in [ 0ms ]
2011-02-09 12:17:53,384 QuartzWorker-0 INFO ServiceRunner     [directory.ldap.cache.AbstractCacheRefresher] found [ 0 ] remote group-group memberships in [ 0ms ]
2011-02-09 12:17:53,385 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 0 ] group members from [ jira-users-xx ] in [ 1ms ]
2011-02-09 12:17:53,410 QuartzWorker-0 INFO ServiceRunner     [directory.ldap.cache.AbstractCacheRefresher] found [ 1 ] remote user-group memberships in [ 25ms ]
2011-02-09 12:17:53,411 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 1 ] user members from [ little-admin ] in [ 1ms ]
2011-02-09 12:17:53,411 QuartzWorker-0 INFO ServiceRunner     [directory.ldap.cache.AbstractCacheRefresher] found [ 0 ] remote group-group memberships in [ 0ms ]
2011-02-09 12:17:53,411 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 0 ] group members from [ little-admin ] in [ 0ms ]
2011-02-09 12:17:53,447 QuartzWorker-0 INFO ServiceRunner     [directory.ldap.cache.AbstractCacheRefresher] found [ 2 ] remote user-group memberships in [ 36ms ]
2011-02-09 12:17:53,448 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 2 ] user members from [ jira-users ] in [ 0ms ]
2011-02-09 12:17:53,448 QuartzWorker-0 INFO ServiceRunner     [directory.ldap.cache.AbstractCacheRefresher] found [ 0 ] remote group-group memberships in [ 0ms ]
2011-02-09 12:17:53,448 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 0 ] group members from [ jira-users ] in [ 0ms ]
2011-02-09 12:17:53,462 QuartzWorker-0 INFO ServiceRunner     [directory.ldap.cache.AbstractCacheRefresher] found [ 0 ] remote user-group memberships in [ 14ms ]
2011-02-09 12:17:53,463 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 0 ] user members from [ testg1 ] in [ 0ms ]
2011-02-09 12:17:53,463 QuartzWorker-0 INFO ServiceRunner     [directory.ldap.cache.AbstractCacheRefresher] found [ 0 ] remote group-group memberships in [ 0ms ]
2011-02-09 12:17:53,463 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectoryCache] scanned and compared [ 0 ] group members from [ testg1 ] in [ 0ms ]
2011-02-09 12:17:53,463 QuartzWorker-0 INFO ServiceRunner     [atlassian.crowd.directory.DbCachingRemoteDirectory] synchronisation complete in [ 155ms ]
2

            [CWD-3044] Reduce logging during directory synchronization

            Monique Khairuliana (Inactive) made changes -
            Workflow Original: Simplified Crowd Development Workflow v2 - restricted [ 1510893 ] New: JAC Bug Workflow v3 [ 3364267 ]
            Status Original: Resolved [ 5 ] New: Closed [ 6 ]
            vkharisma made changes -
            Link New: This issue is cloned from JRACLOUD-23978 [ JRACLOUD-23978 ]
            Owen made changes -
            Workflow Original: Simplified Crowd Development Workflow v2 [ 1392150 ] New: Simplified Crowd Development Workflow v2 - restricted [ 1510893 ]
            Owen made changes -
            Workflow Original: Crowd Development Workflow v2 [ 455613 ] New: Simplified Crowd Development Workflow v2 [ 1392150 ]
            joe made changes -
            Link New: This issue causes CWD-3241 [ CWD-3241 ]
            Diego Berrueta made changes -
            Remote Link New: This issue links to "Wiki Page (Extranet)" [ 38053 ]
            joe made changes -
            Summary Original: JIRA Logs way too much when doing a user directory synchronize New: Reduce logging during directory synchronization
            joe made changes -
            Fix Version/s New: 2.6.1 [ 30697 ]
            Resolution New: Fixed [ 1 ]
            Status Original: Technical Review [ 10028 ] New: Resolved [ 5 ]

            joe added a comment -

            With this fix logging is reduced significantly. Progress is now logged for processes that take over a minute.

            Here's an example where the first few stages completed before that interval so they only have the fixed INFO log lines. Synchronisation of memberships took longer so percentage-complete lines are logged approximately once per minute:

            INFO [atlassian.crowd.directory.DbCachingRemoteDirectory] synchronisation for directory [ 15990785 ] starting
INFO [directory.ldap.cache.UsnChangedCacheRefresher] found [ 1001 ] remote groups in [ 13784ms ]
INFO [directory.ldap.cache.UsnChangedCacheRefresher] found [ 10000 ] remote users in [ 21622ms ]
INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 10000 ] users to add or update
INFO [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanned and compared [ 10000 ] users for update in DB cache in [ 4827ms ] 
INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] adding [ 10000 ] users
INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] added [ 10000 ] users in [ 30383ms ]
INFO [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronised [ 10000 ] users in [ 35214ms ]
INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 10000 ] users for delete in DB cache in [ 114ms ]
INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] scanned for deleted users in [ 120ms ]
INFO [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanning [ 1001 ] groups to add or update
INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 1001 ] groups for update in DB cache in [ 24ms ] 
INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] added [ 1001 ] groups in [ 396ms ]
INFO [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronized [ 1001 ] groups in [ 427ms ]
INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 1001 ] groups for delete in DB cache in [ 20ms ]
INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (114/1001 - 11.4%) 60060ms elapsed
INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (182/1001 - 18.2%) 120073ms elapsed
INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (296/1001 - 29.6%) 180452ms elapsed 
INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (405/1001 - 40.5%) 240654ms elapsed
INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (506/1001 - 50.5%) 301212ms elapsed
INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (612/1001 - 61.1%) 361262ms elapsed
INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (712/1001 - 71.1%) 421296ms elapsed
INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (811/1001 - 81.0%) 481417ms elapsed
INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (912/1001 - 91.1%) 541963ms elapsed
INFO [atlassian.crowd.directory.DbCachingRemoteDirectory] FULL synchronisation complete in [ 656508ms ]

            joe added a comment - With this fix logging is reduced significantly. Progress is now logged for processes that take over a minute. Here's an example where the first few stages completed before that interval so they only have the fixed INFO log lines. Synchronisation of memberships took longer so percentage-complete lines are logged approximately once per minute: INFO [atlassian.crowd.directory.DbCachingRemoteDirectory] synchronisation for directory [ 15990785 ] starting INFO [directory.ldap.cache.UsnChangedCacheRefresher] found [ 1001 ] remote groups in [ 13784ms ] INFO [directory.ldap.cache.UsnChangedCacheRefresher] found [ 10000 ] remote users in [ 21622ms ] INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] scanning [ 10000 ] users to add or update INFO [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanned and compared [ 10000 ] users for update in DB cache in [ 4827ms ] INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] adding [ 10000 ] users INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] added [ 10000 ] users in [ 30383ms ] INFO [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronised [ 10000 ] users in [ 35214ms ] INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 10000 ] users for delete in DB cache in [ 114ms ] INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] scanned for deleted users in [ 120ms ] INFO [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] scanning [ 1001 ] groups to add or update INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 1001 ] groups for update in DB cache in [ 24ms ] INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] added [ 1001 ] groups in [ 396ms ] INFO [atlassian.crowd.directory.DirectoryCacheImplUsingChangeOperations] synchronized [ 1001 ] groups in [ 427ms ] INFO [atlassian.crowd.directory.DbCachingRemoteChangeOperations] scanned and compared [ 1001 ] groups for delete in DB cache in [ 20ms ] INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (114/1001 - 11.4%) 60060ms elapsed INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (182/1001 - 18.2%) 120073ms elapsed INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (296/1001 - 29.6%) 180452ms elapsed INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (405/1001 - 40.5%) 240654ms elapsed INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (506/1001 - 50.5%) 301212ms elapsed INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (612/1001 - 61.1%) 361262ms elapsed INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (712/1001 - 71.1%) 421296ms elapsed INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (811/1001 - 81.0%) 481417ms elapsed INFO [directory.ldap.cache.AbstractCacheRefresher] migrated memberships for group - (912/1001 - 91.1%) 541963ms elapsed INFO [atlassian.crowd.directory.DbCachingRemoteDirectory] FULL synchronisation complete in [ 656508ms ]
            joe made changes -
            Status Original: In Progress [ 3 ] New: Technical Review [ 10028 ]

              jwalton joe
              bbain bain
              Affected customers:
              1 This affects my team
              Watchers:
              3 Start watching this issue

                Created:
                Updated:
                Resolved: