server icon indicating copy to clipboard operation
server copied to clipboard
verified publisher icon nextcloud

[Bug]: Anomalous increase in attempts to update last activity/check

Open RaitoBezarius opened this issue 3 years ago • 0 comments

⚠️ This issue respects the following points: ⚠️

  • [X] This is a bug, not a question or a configuration/webserver/proxy issue.
  • [X] This issue is not already reported on Github (I've searched it).
  • [X] Nextcloud Server is up to date. See Maintenance and Release Schedule for supported versions.
  • [X] Nextcloud Server is running on 64bit capable CPU, PHP and OS.
  • [X] I agree to follow Nextcloud's Code of Conduct.

Bug description

I am running a PHPFPM+NGINX+NextCloud on a NixOS machine.

I am seeing anomalous increases in attempts from NextCloud to update last activity/check in PostgreSQL database that result in resource exhaustion and potentially deadlocks, see attached logs:

nov. 30 02:30:07 productivity postgres[1383107]: [1383107] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:07 productivity postgres[1383107]: [1383107] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:07 productivity postgres[1383071]: [1383071] LOG:  process 1383071 still waiting for ShareLock on transaction 803394 after 1002.739 ms
nov. 30 02:30:07 productivity postgres[1383071]: [1383071] DETAIL:  Process holding the lock: 1383240. Wait queue: 1383074, 1383238, 1382516, 1383104, 1382519, 1382514, 1382947, 1382520, 1383233, 1383069, 1383072, 1383253, 1382958, 1383105, 1382948, 1383078, 1383248, 1382198, 1383083, 1382956, 1382552, 1383081, 1382963, 1383088, 1382946, 1382945, 1381422, 1383075, 1382949, 1382960, 1383079, 1382977, 1383242, 1383077, 1382528, 1382533, 1383070, 1382522, 1382959, 1383106, 1383076, 1383111, 1383112, 1383089, 1381431, 1383082, 1382952, 1382518, 1383244, 1383080, 1383085, 1381414, 1382950, 1382515, 1382570, 1382512, 1383073, 1383107, 1383108, 1381417, 1383237, 1383071, 1382976, 1383241, 1383232, 1382944, 1383247, 1382524, 1383234.
nov. 30 02:30:07 productivity postgres[1383071]: [1383071] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:07 productivity postgres[1383071]: [1383071] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:07 productivity postgres[1382976]: [1382976] LOG:  process 1382976 still waiting for ShareLock on transaction 803394 after 1002.757 ms
nov. 30 02:30:07 productivity postgres[1382976]: [1382976] DETAIL:  Process holding the lock: 1383240. Wait queue: 1383074, 1383238, 1382516, 1383104, 1382519, 1382514, 1382947, 1382520, 1383233, 1383069, 1383072, 1383253, 1382958, 1383105, 1382948, 1383078, 1383248, 1382198, 1383083, 1382956, 1382552, 1383081, 1382963, 1383088, 1382946, 1382945, 1381422, 1383075, 1382949, 1382960, 1383079, 1382977, 1383242, 1383077, 1382528, 1382533, 1383070, 1382522, 1382959, 1383106, 1383076, 1383111, 1383112, 1383089, 1381431, 1383082, 1382952, 1382518, 1383244, 1383080, 1383085, 1381414, 1382950, 1382515, 1382570, 1382512, 1383073, 1383107, 1383108, 1381417, 1383237, 1383071, 1382976, 1383241, 1383232, 1382944, 1383247, 1382524, 1383234.
nov. 30 02:30:07 productivity postgres[1382976]: [1382976] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:07 productivity postgres[1382976]: [1382976] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:07 productivity postgres[1383241]: [1383241] LOG:  process 1383241 still waiting for ShareLock on transaction 803394 after 1002.823 ms
nov. 30 02:30:07 productivity postgres[1383241]: [1383241] DETAIL:  Process holding the lock: 1383240. Wait queue: 1383074, 1383238, 1382516, 1383104, 1382519, 1382514, 1382947, 1382520, 1383233, 1383069, 1383072, 1383253, 1382958, 1383105, 1382948, 1383078, 1383248, 1382198, 1383083, 1382956, 1382552, 1383081, 1382963, 1383088, 1382946, 1382945, 1381422, 1383075, 1382949, 1382960, 1383079, 1382977, 1383242, 1383077, 1382528, 1382533, 1383070, 1382522, 1382959, 1383106, 1383076, 1383111, 1383112, 1383089, 1381431, 1383082, 1382952, 1382518, 1383244, 1383080, 1383085, 1381414, 1382950, 1382515, 1382570, 1382512, 1383073, 1383107, 1383108, 1381417, 1383237, 1383071, 1382976, 1383241, 1383232, 1382944, 1383247, 1382524, 1383234.
nov. 30 02:30:07 productivity postgres[1383241]: [1383241] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:07 productivity postgres[1383241]: [1383241] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:07 productivity postgres[1383232]: [1383232] LOG:  process 1383232 still waiting for ShareLock on transaction 803394 after 1002.644 ms
nov. 30 02:30:07 productivity postgres[1383232]: [1383232] DETAIL:  Process holding the lock: 1383240. Wait queue: 1383074, 1383238, 1382516, 1383104, 1382519, 1382514, 1382947, 1382520, 1383233, 1383069, 1383072, 1383253, 1382958, 1383105, 1382948, 1383078, 1383248, 1382198, 1383083, 1382956, 1382552, 1383081, 1382963, 1383088, 1382946, 1382945, 1381422, 1383075, 1382949, 1382960, 1383079, 1382977, 1383242, 1383077, 1382528, 1382533, 1383070, 1382522, 1382959, 1383106, 1383076, 1383111, 1383112, 1383089, 1381431, 1383082, 1382952, 1382518, 1383244, 1383080, 1383085, 1381414, 1382950, 1382515, 1382570, 1382512, 1383073, 1383107, 1383108, 1381417, 1383237, 1383071, 1382976, 1383241, 1383232, 1382944, 1383247, 1382524, 1383234.
nov. 30 02:30:07 productivity postgres[1383232]: [1383232] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:07 productivity postgres[1383232]: [1383232] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:07 productivity postgres[1383234]: [1383234] LOG:  process 1383234 still waiting for ShareLock on transaction 803394 after 1002.197 ms
nov. 30 02:30:07 productivity postgres[1383234]: [1383234] DETAIL:  Process holding the lock: 1383240. Wait queue: 1383074, 1383238, 1382516, 1383104, 1382519, 1382514, 1382947, 1382520, 1383233, 1383069, 1383072, 1383253, 1382958, 1383105, 1382948, 1383078, 1383248, 1382198, 1383083, 1382956, 1382552, 1383081, 1382963, 1383088, 1382946, 1382945, 1381422, 1383075, 1382949, 1382960, 1383079, 1382977, 1383242, 1383077, 1382528, 1382533, 1383070, 1382522, 1382959, 1383106, 1383076, 1383111, 1383112, 1383089, 1381431, 1383082, 1382952, 1382518, 1383244, 1383080, 1383085, 1381414, 1382950, 1382515, 1382570, 1382512, 1383073, 1383107, 1383108, 1381417, 1383237, 1383071, 1382976, 1383241, 1383232, 1382944, 1383247, 1382524, 1383234.
nov. 30 02:30:07 productivity postgres[1383234]: [1383234] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:07 productivity postgres[1383234]: [1383234] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:07 productivity postgres[1382524]: [1382524] LOG:  process 1382524 still waiting for ShareLock on transaction 803394 after 1002.407 ms
nov. 30 02:30:07 productivity postgres[1382524]: [1382524] DETAIL:  Process holding the lock: 1383240. Wait queue: 1383074, 1383238, 1382516, 1383104, 1382519, 1382514, 1382947, 1382520, 1383233, 1383069, 1383072, 1383253, 1382958, 1383105, 1382948, 1383078, 1383248, 1382198, 1383083, 1382956, 1382552, 1383081, 1382963, 1383088, 1382946, 1382945, 1381422, 1383075, 1382949, 1382960, 1383079, 1382977, 1383242, 1383077, 1382528, 1382533, 1383070, 1382522, 1382959, 1383106, 1383076, 1383111, 1383112, 1383089, 1381431, 1383082, 1382952, 1382518, 1383244, 1383080, 1383085, 1381414, 1382950, 1382515, 1382570, 1382512, 1383073, 1383107, 1383108, 1381417, 1383237, 1383071, 1382976, 1383241, 1383232, 1382944, 1383247, 1382524, 1383234.
nov. 30 02:30:07 productivity postgres[1382524]: [1382524] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:07 productivity postgres[1382524]: [1382524] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1382524]: [1382524] LOG:  process 1382524 acquired ShareLock on transaction 803394 after 10417.902 ms
nov. 30 02:30:16 productivity postgres[1382524]: [1382524] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1382524]: [1382524] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1383241]: [1383241] LOG:  process 1383241 acquired ShareLock on transaction 803394 after 10418.598 ms
nov. 30 02:30:16 productivity postgres[1383241]: [1383241] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1383241]: [1383241] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1382518]: [1382518] LOG:  process 1382518 acquired ShareLock on transaction 803394 after 10420.033 ms
nov. 30 02:30:16 productivity postgres[1382518]: [1382518] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1382518]: [1382518] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1383108]: [1383108] LOG:  process 1383108 acquired ShareLock on transaction 803394 after 10419.024 ms
nov. 30 02:30:16 productivity postgres[1383108]: [1383108] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1383108]: [1383108] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:16 productivity postgres[1382944]: [1382944] LOG:  process 1382944 acquired ShareLock on transaction 803394 after 10418.460 ms
nov. 30 02:30:16 productivity postgres[1382944]: [1382944] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1382944]: [1382944] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1383244]: [1383244] LOG:  process 1383244 acquired ShareLock on transaction 803394 after 10419.971 ms
nov. 30 02:30:16 productivity postgres[1383244]: [1383244] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1383244]: [1383244] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1383248]: [1383248] LOG:  process 1383248 acquired ShareLock on transaction 803394 after 10422.959 ms
nov. 30 02:30:16 productivity postgres[1383248]: [1383248] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1383248]: [1383248] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1382949]: [1382949] LOG:  process 1382949 acquired ShareLock on transaction 803394 after 10421.785 ms
nov. 30 02:30:16 productivity postgres[1382949]: [1382949] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1382949]: [1382949] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1382976]: [1382976] LOG:  process 1382976 acquired ShareLock on transaction 803394 after 10418.849 ms
nov. 30 02:30:16 productivity postgres[1382976]: [1382976] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1382976]: [1382976] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1383233]: [1383233] LOG:  process 1383233 acquired ShareLock on transaction 803394 after 10423.680 ms
nov. 30 02:30:16 productivity postgres[1383233]: [1383233] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1383233]: [1383233] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1382950]: [1382950] LOG:  process 1382950 acquired ShareLock on transaction 803394 after 10419.995 ms
nov. 30 02:30:16 productivity postgres[1382950]: [1382950] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1382950]: [1382950] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1383112]: [1383112] LOG:  process 1383112 acquired ShareLock on transaction 803394 after 10420.424 ms
nov. 30 02:30:16 productivity postgres[1383112]: [1383112] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1383112]: [1383112] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:16 productivity postgres[1383076]: [1383076] LOG:  process 1383076 acquired ShareLock on transaction 803394 after 10420.557 ms
nov. 30 02:30:16 productivity postgres[1383076]: [1383076] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1383076]: [1383076] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:16 productivity postgres[1383083]: [1383083] LOG:  process 1383083 acquired ShareLock on transaction 803394 after 10422.573 ms
nov. 30 02:30:16 productivity postgres[1383083]: [1383083] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1383083]: [1383083] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:16 productivity postgres[1382948]: [1382948] LOG:  process 1382948 acquired ShareLock on transaction 803394 after 10423.289 ms
nov. 30 02:30:16 productivity postgres[1382948]: [1382948] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1382948]: [1382948] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1382947]: [1382947] LOG:  process 1382947 acquired ShareLock on transaction 803394 after 10425.020 ms
nov. 30 02:30:16 productivity postgres[1382947]: [1382947] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1382947]: [1382947] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1382552]: [1382552] LOG:  process 1382552 acquired ShareLock on transaction 803394 after 10422.587 ms
nov. 30 02:30:16 productivity postgres[1382552]: [1382552] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1382552]: [1382552] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:16 productivity postgres[1383253]: [1383253] LOG:  process 1383253 acquired ShareLock on transaction 803394 after 10423.235 ms
nov. 30 02:30:16 productivity postgres[1383253]: [1383253] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1383253]: [1383253] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1383085]: [1383085] LOG:  process 1383085 acquired ShareLock on transaction 803394 after 10420.444 ms
nov. 30 02:30:16 productivity postgres[1383085]: [1383085] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1383085]: [1383085] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1383089]: [1383089] LOG:  process 1383089 acquired ShareLock on transaction 803394 after 10420.404 ms
nov. 30 02:30:16 productivity postgres[1383089]: [1383089] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1383089]: [1383089] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:16 productivity postgres[1382956]: [1382956] LOG:  process 1382956 acquired ShareLock on transaction 803394 after 10422.653 ms
nov. 30 02:30:16 productivity postgres[1382956]: [1382956] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1382956]: [1382956] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1381431]: [1381431] LOG:  process 1381431 acquired ShareLock on transaction 803394 after 10420.315 ms
nov. 30 02:30:16 productivity postgres[1381431]: [1381431] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1381431]: [1381431] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:16 productivity postgres[1382533]: [1382533] LOG:  process 1382533 acquired ShareLock on transaction 803394 after 10421.489 ms
nov. 30 02:30:16 productivity postgres[1382533]: [1382533] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:16 productivity postgres[1382533]: [1382533] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383080]: [1383080] LOG:  process 1383080 acquired ShareLock on transaction 803394 after 10419.745 ms
nov. 30 02:30:17 productivity postgres[1383080]: [1383080] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383080]: [1383080] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1382528]: [1382528] LOG:  process 1382528 acquired ShareLock on transaction 803394 after 10421.387 ms
nov. 30 02:30:17 productivity postgres[1382528]: [1382528] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382528]: [1382528] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383079]: [1383079] LOG:  process 1383079 acquired ShareLock on transaction 803394 after 10421.682 ms
nov. 30 02:30:17 productivity postgres[1383079]: [1383079] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383079]: [1383079] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383072]: [1383072] LOG:  process 1383072 acquired ShareLock on transaction 803394 after 10425.054 ms
nov. 30 02:30:17 productivity postgres[1383072]: [1383072] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383072]: [1383072] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1382570]: [1382570] LOG:  process 1382570 acquired ShareLock on transaction 803394 after 10419.353 ms
nov. 30 02:30:17 productivity postgres[1382570]: [1382570] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382570]: [1382570] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382958]: [1382958] LOG:  process 1382958 acquired ShareLock on transaction 803394 after 10423.049 ms
nov. 30 02:30:17 productivity postgres[1382958]: [1382958] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382958]: [1382958] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383104]: [1383104] LOG:  process 1383104 acquired ShareLock on transaction 803394 after 10423.763 ms
nov. 30 02:30:17 productivity postgres[1383104]: [1383104] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383104]: [1383104] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383078]: [1383078] LOG:  process 1383078 acquired ShareLock on transaction 803394 after 10422.816 ms
nov. 30 02:30:17 productivity postgres[1383078]: [1383078] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383078]: [1383078] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1381414]: [1381414] LOG:  process 1381414 acquired ShareLock on transaction 803394 after 10420.997 ms
nov. 30 02:30:17 productivity postgres[1381414]: [1381414] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1381414]: [1381414] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383242]: [1383242] LOG:  process 1383242 acquired ShareLock on transaction 803394 after 10421.317 ms
nov. 30 02:30:17 productivity postgres[1383242]: [1383242] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383242]: [1383242] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382515]: [1382515] LOG:  process 1382515 acquired ShareLock on transaction 803394 after 10420.835 ms
nov. 30 02:30:17 productivity postgres[1382515]: [1382515] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382515]: [1382515] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383238]: [1383238] LOG:  process 1383238 acquired ShareLock on transaction 803394 after 10423.882 ms
nov. 30 02:30:17 productivity postgres[1383238]: [1383238] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383238]: [1383238] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383082]: [1383082] LOG:  process 1383082 acquired ShareLock on transaction 803394 after 10421.702 ms
nov. 30 02:30:17 productivity postgres[1383082]: [1383082] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383082]: [1383082] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382522]: [1382522] LOG:  process 1382522 acquired ShareLock on transaction 803394 after 10420.854 ms
nov. 30 02:30:17 productivity postgres[1382522]: [1382522] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382522]: [1382522] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382520]: [1382520] LOG:  process 1382520 acquired ShareLock on transaction 803394 after 10423.331 ms
nov. 30 02:30:17 productivity postgres[1382520]: [1382520] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382520]: [1382520] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383081]: [1383081] LOG:  process 1383081 acquired ShareLock on transaction 803394 after 10422.704 ms
nov. 30 02:30:17 productivity postgres[1383081]: [1383081] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383081]: [1383081] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1382512]: [1382512] LOG:  process 1382512 acquired ShareLock on transaction 803394 after 10420.821 ms
nov. 30 02:30:17 productivity postgres[1382512]: [1382512] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382512]: [1382512] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383111]: [1383111] LOG:  process 1383111 acquired ShareLock on transaction 803394 after 10422.299 ms
nov. 30 02:30:17 productivity postgres[1383111]: [1383111] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383111]: [1383111] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382198]: [1382198] LOG:  process 1382198 acquired ShareLock on transaction 803394 after 10422.817 ms
nov. 30 02:30:17 productivity postgres[1382198]: [1382198] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382198]: [1382198] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382959]: [1382959] LOG:  process 1382959 acquired ShareLock on transaction 803394 after 10422.810 ms
nov. 30 02:30:17 productivity postgres[1382959]: [1382959] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382959]: [1382959] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382519]: [1382519] LOG:  process 1382519 acquired ShareLock on transaction 803394 after 10423.467 ms
nov. 30 02:30:17 productivity postgres[1382519]: [1382519] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382519]: [1382519] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382977]: [1382977] LOG:  process 1382977 acquired ShareLock on transaction 803394 after 10421.572 ms
nov. 30 02:30:17 productivity postgres[1382977]: [1382977] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382977]: [1382977] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383107]: [1383107] LOG:  process 1383107 acquired ShareLock on transaction 803394 after 10419.048 ms
nov. 30 02:30:17 productivity postgres[1383107]: [1383107] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383107]: [1383107] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383075]: [1383075] LOG:  process 1383075 acquired ShareLock on transaction 803394 after 10424.375 ms
nov. 30 02:30:17 productivity postgres[1383075]: [1383075] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383075]: [1383075] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383071]: [1383071] LOG:  process 1383071 acquired ShareLock on transaction 803394 after 10420.602 ms
nov. 30 02:30:17 productivity postgres[1383071]: [1383071] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383071]: [1383071] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382516]: [1382516] LOG:  process 1382516 acquired ShareLock on transaction 803394 after 10423.827 ms
nov. 30 02:30:17 productivity postgres[1382516]: [1382516] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382516]: [1382516] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383073]: [1383073] LOG:  process 1383073 acquired ShareLock on transaction 803394 after 10419.214 ms
nov. 30 02:30:17 productivity postgres[1383073]: [1383073] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383073]: [1383073] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383088]: [1383088] LOG:  process 1383088 acquired ShareLock on transaction 803394 after 10425.112 ms
nov. 30 02:30:17 productivity postgres[1383088]: [1383088] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383088]: [1383088] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383106]: [1383106] LOG:  process 1383106 acquired ShareLock on transaction 803394 after 10420.838 ms
nov. 30 02:30:17 productivity postgres[1383106]: [1383106] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383106]: [1383106] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383232]: [1383232] LOG:  process 1383232 acquired ShareLock on transaction 803394 after 10420.659 ms
nov. 30 02:30:17 productivity postgres[1383232]: [1383232] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383232]: [1383232] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383070]: [1383070] LOG:  process 1383070 acquired ShareLock on transaction 803394 after 10420.861 ms
nov. 30 02:30:17 productivity postgres[1383070]: [1383070] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383070]: [1383070] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1382514]: [1382514] LOG:  process 1382514 acquired ShareLock on transaction 803394 after 10423.784 ms
nov. 30 02:30:17 productivity postgres[1382514]: [1382514] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382514]: [1382514] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382960]: [1382960] LOG:  process 1382960 acquired ShareLock on transaction 803394 after 10421.643 ms
nov. 30 02:30:17 productivity postgres[1382960]: [1382960] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382960]: [1382960] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382950]: [1382950] LOG:  duration: 436071.876 ms  execute <unnamed>: UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382950]: [1382950] DETAIL:  parameters: $1 = '1669771380', $2 = '179', $3 = '1669771365'
nov. 30 02:30:17 productivity postgres[1383069]: [1383069] LOG:  process 1383069 acquired ShareLock on transaction 803394 after 10423.808 ms
nov. 30 02:30:17 productivity postgres[1383069]: [1383069] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383069]: [1383069] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383247]: [1383247] LOG:  process 1383247 acquired ShareLock on transaction 803394 after 10421.310 ms
nov. 30 02:30:17 productivity postgres[1383247]: [1383247] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383247]: [1383247] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382952]: [1382952] LOG:  process 1382952 acquired ShareLock on transaction 803394 after 10420.233 ms
nov. 30 02:30:17 productivity postgres[1382952]: [1382952] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382952]: [1382952] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383234]: [1383234] LOG:  process 1383234 acquired ShareLock on transaction 803394 after 10420.975 ms
nov. 30 02:30:17 productivity postgres[1383234]: [1383234] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383234]: [1383234] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383077]: [1383077] LOG:  process 1383077 acquired ShareLock on transaction 803394 after 10421.618 ms
nov. 30 02:30:17 productivity postgres[1383077]: [1383077] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383077]: [1383077] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383074]: [1383074] LOG:  process 1383074 acquired ShareLock on transaction 803394 after 10427.913 ms
nov. 30 02:30:17 productivity postgres[1383074]: [1383074] CONTEXT:  while locking tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383074]: [1383074] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382963]: [1382963] LOG:  process 1382963 acquired ShareLock on transaction 803394 after 10422.192 ms
nov. 30 02:30:17 productivity postgres[1382963]: [1382963] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382963]: [1382963] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382945]: [1382945] LOG:  process 1382945 acquired ShareLock on transaction 803394 after 10422.308 ms
nov. 30 02:30:17 productivity postgres[1382945]: [1382945] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382945]: [1382945] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1381417]: [1381417] LOG:  process 1381417 acquired ShareLock on transaction 803394 after 10423.113 ms
nov. 30 02:30:17 productivity postgres[1381417]: [1381417] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1381417]: [1381417] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383237]: [1383237] LOG:  process 1383237 acquired ShareLock on transaction 803394 after 10423.036 ms
nov. 30 02:30:17 productivity postgres[1383237]: [1383237] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383237]: [1383237] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1381422]: [1381422] LOG:  process 1381422 acquired ShareLock on transaction 803394 after 10422.312 ms
nov. 30 02:30:17 productivity postgres[1381422]: [1381422] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1381422]: [1381422] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382946]: [1382946] LOG:  process 1382946 acquired ShareLock on transaction 803394 after 10422.437 ms
nov. 30 02:30:17 productivity postgres[1382946]: [1382946] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1382946]: [1382946] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383105]: [1383105] LOG:  process 1383105 acquired ShareLock on transaction 803394 after 10426.324 ms
nov. 30 02:30:17 productivity postgres[1383105]: [1383105] CONTEXT:  while rechecking updated tuple (17,5) in relation "oc_authtoken"
nov. 30 02:30:17 productivity postgres[1383105]: [1383105] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1382571]: [1382571] LOG:  process 1382571 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10433.977 ms
nov. 30 02:30:17 productivity postgres[1382571]: [1382571] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382954]: [1382954] LOG:  process 1382954 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.338 ms
nov. 30 02:30:17 productivity postgres[1382954]: [1382954] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382513]: [1382513] LOG:  process 1382513 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.056 ms
nov. 30 02:30:17 productivity postgres[1382513]: [1382513] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383235]: [1383235] LOG:  process 1383235 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.299 ms
nov. 30 02:30:17 productivity postgres[1383235]: [1383235] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382572]: [1382572] LOG:  process 1382572 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.410 ms
nov. 30 02:30:17 productivity postgres[1382572]: [1382572] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383236]: [1383236] LOG:  process 1383236 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.519 ms
nov. 30 02:30:17 productivity postgres[1383236]: [1383236] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383239]: [1383239] LOG:  process 1383239 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.713 ms
nov. 30 02:30:17 productivity postgres[1383239]: [1383239] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382534]: [1382534] LOG:  process 1382534 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.816 ms
nov. 30 02:30:17 productivity postgres[1382534]: [1382534] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382196]: [1382196] LOG:  process 1382196 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.972 ms
nov. 30 02:30:17 productivity postgres[1382196]: [1382196] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382189]: [1382189] LOG:  process 1382189 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10435.196 ms
nov. 30 02:30:17 productivity postgres[1382189]: [1382189] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1383110]: [1383110] LOG:  process 1383110 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10435.347 ms
nov. 30 02:30:17 productivity postgres[1383110]: [1383110] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383068]: [1383068] LOG:  process 1383068 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10435.396 ms
nov. 30 02:30:17 productivity postgres[1383068]: [1383068] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1381452]: [1381452] LOG:  process 1381452 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10435.004 ms
nov. 30 02:30:17 productivity postgres[1381452]: [1381452] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382525]: [1382525] LOG:  process 1382525 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10435.105 ms
nov. 30 02:30:17 productivity postgres[1382525]: [1382525] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1382517]: [1382517] LOG:  process 1382517 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.643 ms
nov. 30 02:30:17 productivity postgres[1382517]: [1382517] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382553]: [1382553] LOG:  process 1382553 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.782 ms
nov. 30 02:30:17 productivity postgres[1382553]: [1382553] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382555]: [1382555] LOG:  process 1382555 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.671 ms
nov. 30 02:30:17 productivity postgres[1382555]: [1382555] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382955]: [1382955] LOG:  process 1382955 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.851 ms
nov. 30 02:30:17 productivity postgres[1382955]: [1382955] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382951]: [1382951] LOG:  process 1382951 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.946 ms
nov. 30 02:30:17 productivity postgres[1382951]: [1382951] STATEMENT:  UPDATE "oc_authtoken" SET "last_activity" = $1 WHERE ("id" = $2) AND ("last_activity" < $3)
nov. 30 02:30:17 productivity postgres[1382523]: [1382523] LOG:  process 1382523 acquired ExclusiveLock on tuple (17,5) of relation 16451 of database 16384 after 10434.301 ms
nov. 30 02:30:17 productivity postgres[1382523]: [1382523] STATEMENT:  UPDATE "oc_authtoken" SET "last_check" = $1 WHERE "id" = $2
nov. 30 02:30:17 productivity postgres[1383072]: [1383072] LOG:  process 1383072 still waiting for ExclusiveLock on tuple (17,6) of relation 16451 of database 16384 after 1000.442 ms
nov. 30 02:30:17 productivity postgres[1383072]: [1383072] DETAIL:  Process holding the lock: 1382528. Wait queue: 1383072, 1383104, 1383079, 1383078, 1382949, 1383108, 1382976, 1382552, 1383238, 1382959, 1383082, 1382948, 1382516, 1383071, 1383106, 1383232, 1383070, 1383241, 1382522, 1382518, 1383242, 1383081, 1383085, 1382524, 1383111, 1382956, 1383107, 1382198, 1383083, 1382520, 1383112, 1382952, 1383089, 1383075, 1383247, 1383253, 1383234, 1382947, 1383077, 1383233, 1382533, 1381414, 1382945, 1383244, 1382512, 1382570, 1381417, 1382514, 1383237, 1383080, 1383069, 1383073, 1382944, 1383248, 1382958, 1383076, 1383088, 1382519, 1381422, 1382946, 1382963, 1381431, 1382977, 1382960, 1383105, 1382515, 1383074, 1382571, 1382954, 1382513, 1383235, 1382572, 1383236, 1383239, 1382534, 1382196, 1382189, 1383110, 1383068, 1381452, 1382525, 1382517, 1382553, 1382555, 1382955, 1382951, 1382523.

These processes seems to be PHPFPM spawning more and more children due to frontend sending more and more requests.

I do not really know if this is my bad of having PHPFPM going too far, it looks strange to me that backend is trying so much to update and not doing any kind of rate-limiting on this.

Steps to reproduce

  1. Have some bots (vdirsyncer every 5 minutes, phone sync, etc.) on a NextCloud user
  2. Resource constrained machine (4GiB RAM, 8 vCPU, slow disk, ~fast PostgreSQL (high work_mem, maintenance_work_mem, etc.))
  3. Aggressive dynamic PHPFPM: max_children=128, min_spare=8, max_spare=16

Expected behavior

NextCloud should rate-limit last act/check updates to prevent locking deadlocks/exhaustion.

Installation method

Other Community project

Operating system

Other

PHP engine version

PHP 8.1

Web server

Nginx

Database engine version

PostgreSQL

Is this bug present after an update or on a fresh install?

Updated to a major version (ex. 22.2.3 to 23.0.1)

Are you using the Nextcloud Server Encryption module?

Encryption is Disabled

What user-backends are you using?

  • [ ] Default user-backend (database)
  • [ ] LDAP/ Active Directory
  • [X] SSO - SAML
  • [ ] Other

Configuration report

{
    "system": {
        "apps_paths": [
            {
                "path": "\/var\/lib\/nextcloud\/apps",
                "url": "\/apps",
                "writable": false
            },
            {
                "path": "\/var\/lib\/nextcloud\/store-apps",
                "url": "\/store-apps",
                "writable": true
            }
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "skeletondirectory": "",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "log_type": "syslog",
        "log_level": "2",
        "overwriteprotocol": "https",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "pgsql",
        "trusted_proxies": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "version": "25.0.1.1",
        "overwrite.cli.url": "https:\/\/localhost",
        "dbport": "",
        "dbtableprefix": "oc_",
        "installed": true,
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpmode": "smtp",
        "mail_sendmailmode": "smtp",
        "mail_smtpauth": 1,
        "mail_smtpsecure": "ssl",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "465",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpauthtype": "PLAIN",
        "maintenance": false,
        "theme": "",
        "loglevel": "2",
        "profile.enabled": false,
        "data-fingerprint": "7c2c00aa1a3a2bdf460cd4a47fc497f9",
        "trusted_domains": [
            "my.nextcloud.tld"
        ]
    }
}

List of activated Apps

Enabled:
  - admin_audit: 1.15.0
  - calendar: 4.1.0
  - circles: 25.0.0
  - cloud_federation_api: 1.8.0
  - collectives: 2.1.0
  - comments: 1.15.0
  - contacts: 5.0.1
  - contactsinteraction: 1.6.0
  - cospend: 1.5.4
  - dashboard: 7.5.0
  - dav: 1.24.0
  - event_update_notification: 2.0.0
  - federatedfilesharing: 1.15.0
  - files: 1.20.1
  - files_pdfviewer: 2.6.0
  - files_rightclick: 1.4.0
  - files_sharing: 1.17.0
  - files_trashbin: 1.15.0
  - files_versions: 1.18.0
  - firstrunwizard: 2.14.0
  - forms: 3.0.1
  - guests: 2.3.0
  - integration_google: 1.0.8
  - integration_onedrive: 1.1.4
  - logreader: 2.10.0
  - lookup_server_connector: 1.13.0
  - metadata: 0.17.0
  - nextcloud_announcements: 1.14.0
  - notifications: 2.13.1
  - oauth2: 1.13.0
  - password_policy: 1.15.0
  - photos: 2.0.0
  - polls: 4.0.0
  - privacy: 1.9.0
  - provisioning_api: 1.15.0
  - recommendations: 1.4.0
  - related_resources: 1.0.3
  - serverinfo: 1.15.0
  - settings: 1.7.0
  - sharebymail: 1.15.0
  - support: 1.8.0
  - survey_client: 1.13.0
  - systemtags: 1.15.0
  - tasks: 0.14.5
  - text: 3.6.0
  - theming: 2.0.1
  - twofactor_backupcodes: 1.14.0
  - twofactor_totp: 7.0.0
  - updatenotification: 1.15.0
  - user_status: 1.5.0
  - viewer: 1.9.0
  - weather_status: 1.5.0
  - workflowengine: 2.7.0
Disabled:
  - activity: 2.15.0
  - bruteforcesettings
  - electronicsignatures: 2.0.1
  - encryption
  - federation: 1.13.0
  - files_external
  - gestion: 2.2.2
  - onlyoffice: 7.6.8
  - spreed: 15.0.1
  - suspicious_login
  - user_ldap

Nextcloud Signing status

Technical information
=====================
The following list covers which files have failed the integrity check. Please read
the previous linked documentation to learn more about the errors and how to fix
them.

Results
=======
- core
	- INVALID_HASH
		- lib/private/Setup/PostgreSQL.php
		- lib/private/Setup/MySQL.php

Raw output
==========
Array
(
    [core] => Array
        (
            [INVALID_HASH] => Array
                (
                    [lib/private/Setup/PostgreSQL.php] => Array
                        (
                            [expected] => dc806f109e5324389571d57eb01b68d5a7c20eaf449b3cd528eed38c12633b7497cfe13a5396e4bdd2aeb4c4a5c00f138e52e4740dade5dfa69329eeaa58dbbb
                            [current] => 5e13e3045802a04a52e7a5f9c1b18dd0fd3333b206197ce52c493bb02cdb096c96df8503bb7949e95d81e9bbd1e00863f1eaf3a32e6bb1c6a5b8398b284f2876
                        )

                    [lib/private/Setup/MySQL.php] => Array
                        (
                            [expected] => a8e6a7d82a49544da9dfac311de02d76ba7d318038158749e145a8f12d8b228bfa896a49dc2cca3048498ecc2557d1bd57cbf164c8dd112ffc2c3f526ccaf850
                            [current] => d34f96710b82dbc0aff0a15de57f16ca8cb1535d63fc266c6549ae9ae5c2f44507a97fe81d8b7c2963cbd093fe796ba9abbc037d6fad0f6ab7d578f938d847e8
                        )

                )

        )

)

Nextcloud Logs

none

Additional info

We have distro-level patch on the integrity-failed files: https://github.com/NixOS/nixpkgs/issues/192400 — see the patches here: https://github.com/NixOS/nixpkgs/blob/master/pkgs/servers/nextcloud/0001-Setup-remove-custom-dbuser-creation-behavior.patch

RaitoBezarius avatar Nov 30 '22 01:11 RaitoBezarius