Uploaded image for project: 'Artifactory Binary Repository'
  1. Artifactory Binary Repository
  2. RTFACT-20465

Deadlock when overwriting metadata file

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open
    • Priority: 2 - Critical
    • Resolution: Unresolved
    • Affects Version/s: 6.13.1
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None
    • Severity:
      Critical

      Description

      Steps to reproduce:

      1. Start HA with two nodes at least (I've tested with PostgreSQL)
      2. Create a Conan repository and upload package with few revisions.
      3. Create a new Conan repo.
      4. Copy/Move from previous repo to the new Conan repo.
      5. For the thread that try to copy:
      6. It sometimes will fail with
      Could not acquire lock within 120 seconds. Couldn't acquire lock for: 120000 milliseconds

      The error will occur on the index.json file.
      This happens since there is a deadlock between the copy/move to the calculation of the metadata.
      In the logs you can see the following:
      For the thread that try to copy:

      2019-10-27 08:36:03,417 [http-nio-8082-exec-4] [DEBUG] (o.a.s.d.l.s.DbLocksServiceImpl:79) - Acquiring lock for: category: 'conan-center' key: '_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json' owner: 'art2' thread id: '36' thread name: 'http-nio-8082-exec-4'
      2019-10-27 08:36:03,417 [http-nio-8082-exec-4] [TRACE] (o.a.s.d.l.s.DbLocksServiceImpl:88) - Attempting to acquire lock for: category: 'conan-center' key: '_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json' owner: 'art2' thread id: '36' thread name: 'http-nio-8082-exec-4'
      2019-10-27 08:36:03,418 [http-nio-8082-exec-4] [DEBUG] (o.a.s.d.l.d.DbDistributeLocksDao:164) - Failed to insert lock row to the 'distributed_locks' table: LockInfo{category='conan-center', key='_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json', owner='art2', threadId=36, startedTime=1572165363418, threadName='http-nio-8082-exec-4'}. ERROR: duplicate key value violates unique constraint "locks_pk"
      2019-10-27 08:36:03,419 [http-nio-8082-exec-4] [DEBUG] (o.a.s.d.l.d.DbDistributeLocksDao:166) - Failed to insert lock.
      ......
      2019-10-27 08:38:03,417 [http-nio-8082-exec-4] [TRACE] (o.a.s.d.l.s.DbLocksServiceImpl:114) - Waiting while trying to acquiring lock for: category: 'conan-center' key: '_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json' owner: 'art2' thread id: '36' thread name: 'http-nio-8082-exec-4'
      2019-10-27 08:38:03,418 [http-nio-8082-exec-4] [TRACE] (o.a.s.d.l.s.DbLocksServiceImpl:88) - Attempting to acquire lock for: category: 'conan-center' key: '_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json' owner: 'art2' thread id: '36' thread name: 'http-nio-8082-exec-4'
      2019-10-27 08:38:03,419 [http-nio-8082-exec-4] [DEBUG] (o.a.s.d.l.d.DbDistributeLocksDao:164) - Failed to insert lock row to the 'distributed_locks' table: LockInfo{category='conan-center', key='_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json', owner='art2', threadId=36, startedTime=1572165483418, threadName='http-nio-8082-exec-4'}. ERROR: duplicate key value violates unique constraint "locks_pk"
      2019-10-27 08:38:03,419 [http-nio-8082-exec-4] [DEBUG] (o.a.s.d.l.d.DbDistributeLocksDao:166) - Failed to insert lock.
      

      On the side of the thread that doing the calculation of the metadata:

      2019-10-27 08:36:03,415 [art-exec-1] [DEBUG] (o.a.s.d.f.s.FileServiceImpl:186) - Updating file: conan-center:_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json
      
      2019-10-27 08:38:03,845 [art-exec-1] [TRACE] (o.a.s.d.f.s.SqlStorageSession:138) - After completion called on session 7fe1c095-97e8-41c7-b897-4e12f68848e1
      2019-10-27 08:38:03,849 [art-exec-1] [TRACE] (o.a.s.d.f.s.SqlStorageSession:144) - Release resources called on session 7fe1c095-97e8-41c7-b897-4e12f68848e1
      2019-10-27 08:38:03,849 [art-exec-1] [TRACE] (o.a.s.f.l.SessionLockEntry:125) - Releasing WRITE lock on LockEntryId conan-center:_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json
      2019-10-27 08:38:03,849 [art-exec-1] [TRACE] (o.a.s.d.l.p.DbMapLockWrapper:69) - unlock conan-center/_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json
      
      
      2019-10-27 08:38:03,853 [art-exec-1] [DEBUG] (o.a.s.d.l.s.DbLocksServiceImpl:147) - Attempting to release lock for: category: 'conan-center' key: '_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json' thread id: '68' thread name: 'art-exec-1'
      2019-10-27 08:38:03,853 [art-exec-1] [TRACE] (o.a.s.d.l.s.DbLocksServiceImpl:150) - Attempting to release lock from cache for: category: 'conan-center' key: '_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json' owner: 'art2' thread id: '68' thread name: 'art-exec-1'
      2019-10-27 08:38:03,854 [art-exec-1] [TRACE] (o.a.s.d.l.s.DbLocksServiceImpl:155) - Successfully delete lock from cache for: LockInfo{category='conan-center', key='_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json', owner='art2', threadId=68, startedTime=1572165363408, threadName='art-exec-1'}
      2019-10-27 08:38:03,856 [art-exec-1] [TRACE] (o.a.s.d.l.s.DbLocksServiceImpl:167) - Successfully delete lock from cache for: category: 'conan-center' key: '_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7/index.json' owner: 'art2' thread id: '68' thread name: 'art-exec-1'
      2019-10-27 08:38:03,856 [art-exec-1] [INFO ] (o.a.a.c.s.ConanServiceImpl:280) - Conan index calculation for conan-center:_/zlib/1.2.11/_/f52e38c68b0152cea61ff95860f7e66e/package/6cc50b139b9c3d27b3e9042d5f5372d327b3a9f7 finished successfully
      

      The metadata finishing exactly after the copy fails to acquire the lock (waits for 2 minutes)

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              Unassigned
              Reporter:
              alexeiv Alexei Vainshtein
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

                Dates

                Created:
                Updated:

                  Sync Status

                  Connection: RTFACT Sync
                  RTMID-20465 -
                  SYNCHRONIZED
                  • Last Sync Date: