Project

General

Profile

Actions
Copy link

Bug #17172

closed

Concurrent access to node info cache cause exception to be thrown when accessing cache content

Added by Nicolas CHARLES over 4 years ago. Updated over 4 years ago.

Status:
Released
Priority:
N/A
Assignee:
François ARMAND
Category:
Web - Nodes & inventories
Target version:
6.0.6
Pull Request:
https://github.com/Normation/rudder/p...
Severity:
UX impact:
User visibility:
Effort required:
Priority:
0
Name check:
To do
Fix check:
Checked
Regression:

Description

[2020-04-21 04:40:02] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, last modification t
ime: '2020-04-20T19:46:17.000Z' for: '20200420194617.802757Z#000000#000#000000','20200420194617.780901Z#000000#000#000000'
[2020-04-21 04:40:02] DEBUG com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl - NodeInfo cache is up to date, 
Fiber failed.
An unchecked error was produced.
java.util.NoSuchElementException: None.get
        at scala.None$.get(Option.scala:627)
        at scala.None$.get(Option.scala:626)
        at com.normation.rudder.services.nodes.NodeInfoServiceCached.$anonfun$withUpToDateCache$49(NodeInfoService.scala:416)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3368)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3365)
        at zio.internal.FiberContext.evaluateNow(FiberContext.scala:815)
        at zio.internal.FiberContext.$anonfun$evaluateLater$1(FiberContext.scala:687)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

Fiber:Id(1587444001876,1555202) was supposed to continue to:
  a future continuation at com.normation.rudder.services.nodes.NodeInfoServiceCached.withUpToDateCache(NodeInfoService.scala:418)
  a future continuation at zio.ZIO.run(ZIO.scala:1450)
  a future continuation at zio.Semaphore.withPermits(Semaphore.scala:61)
  a future continuation at zio.ZIO$.zio$ZIO$$_succeedRight(ZIO.scala:3358)
  a future continuation at zio.ZIO.run(ZIO.scala:1450)
  a future continuation at zio.ZIO.bracket_(ZIO.scala:244)
  a future continuation at zio.ZIO.run(ZIO.scala:1450)
  a future continuation at zio.ZIO.bracket_(ZIO.scala:244)
  a future continuation at com.normation.zio$ZioRuntime$.runNow(ZioCommons.scala:358)

Fiber:Id(1587444001876,1555202) execution trace:
  at com.normation.rudder.services.nodes.NodeInfoServiceCached.withUpToDateCache(NodeInfoService.scala:416)
  at zio.ZIO.unit(ZIO.scala:1735)
  at com.normation.errors$.effectUioUnit(ZioCommons.scala:66)
  at zio.ZIO.unit(ZIO.scala:1735)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:155)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at zio.ZIO$.bracketExit(ZIO.scala:1987)
  at zio.internal.FiberContext.evaluateNow(FiberContext.scala:527)
  at zio.ZIO.bracket_(ZIO.scala:244)
  at zio.ZIO.run(ZIO.scala:1450)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at com.normation.ZioLogger.logAndForgetResult(ZioCommons.scala:439)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at com.normation.zio$ZioRuntime$.effectBlocking(ZioCommons.scala:354)
  at zio.ZIO.bracket_(ZIO.scala:244)
  at zio.internal.FiberContext.evaluateNow(FiberContext.scala:523)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at com.normation.rudder.services.nodes.NodeInfoServiceCached.withUpToDateCache(NodeInfoService.scala:397)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:155)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at zio.ZIO$.bracketExit(ZIO.scala:1987)
  at zio.internal.FiberContext.evaluateNow(FiberContext.scala:527)
  at zio.ZIO.bracket_(ZIO.scala:244)
  at zio.ZIO.run(ZIO.scala:1450)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:155)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at zio.ZIO$.bracketExit(ZIO.scala:1987)
  at com.normation.ldap.sdk.PooledConnectionProvider.releaseInternalConnection(LDAPConnectionProvider.scala:251)
  at com.normation.ldap.sdk.LDAPConnectionProvider.withCon(LDAPConnectionProvider.scala:117)
  at zio.ZIO.run(ZIO.scala:1450)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:155)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at zio.ZIO$.bracketExit(ZIO.scala:1987)
  at zio.internal.FiberContext.evaluateNow(FiberContext.scala:527)
  at zio.ZIO.bracket_(ZIO.scala:244)
  at zio.ZIO.run(ZIO.scala:1450)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:155)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at zio.ZIO$.bracketExit(ZIO.scala:1987)
  at com.normation.ldap.sdk.PooledConnectionProvider.releaseInternalConnection(LDAPConnectionProvider.scala:251)
  at com.normation.ldap.sdk.LDAPConnectionProvider.withCon(LDAPConnectionProvider.scala:117)
  at zio.ZIO.run(ZIO.scala:1450)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:155)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at zio.ZIO$.bracketExit(ZIO.scala:1987)
  at zio.internal.FiberContext.evaluateNow(FiberContext.scala:527)
  at zio.ZIO.bracket_(ZIO.scala:244)
  at zio.ZIO.run(ZIO.scala:1450)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl.checkUpToDate(NodeInfoService.scala:695)
  at com.normation.errors$IOResult$.effect(ZioCommons.scala:99)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:155)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at zio.ZIO$.bracketExit(ZIO.scala:1987)
  at zio.internal.FiberContext.evaluateNow(FiberContext.scala:527)
  at zio.ZIO.bracket_(ZIO.scala:244)
  at zio.ZIO.run(ZIO.scala:1450)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl.checkUpToDate(NodeInfoService.scala:695)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at com.normation.zio$ZioRuntime$.effectBlocking(ZioCommons.scala:354)
  at zio.ZIO.bracket_(ZIO.scala:244)
  at zio.internal.FiberContext.evaluateNow(FiberContext.scala:523)
  at com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl.checkUpToDate(NodeInfoService.scala:694)
  at com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl.checkUpToDate(NodeInfoService.scala:694)
  at com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl.checkUpToDate(NodeInfoService.scala:679)
  at zio.syntax$ToZio.succeed(syntax.scala:9)
  at com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl.checkUpToDate(NodeInfoService.scala:691)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl.checkUpToDate(NodeInfoService.scala:690)
  at com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl.checkUpToDate(NodeInfoService.scala:680)
  at com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl.checkUpToDate(NodeInfoService.scala:680)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at com.normation.zio$ZioRuntime$.blocking(ZioCommons.scala:350)
  at zio.ZIO.bracket_(ZIO.scala:244)
  at zio.internal.FiberContext.evaluateNow(FiberContext.scala:523)
  at com.normation.ldap.sdk.LDAPConnectionProvider.withCon(LDAPConnectionProvider.scala:117)
  at com.normation.ldap.sdk.LDAPIOResult$.effectNonBlocking(LDAPIOResult.scala:64)
  at com.normation.errors$IOResult$.effectNonBlocking(ZioCommons.scala:93)
  at com.normation.ldap.sdk.ROPooledSimpleAuthConnectionProvider.newConnection(LDAPConnectionProvider.scala:393)
  at zio.ZIO.bracket_(ZIO.scala:244)
  at zio.internal.FiberContext.evaluateNow(FiberContext.scala:523)
  at com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl.checkUpToDate(NodeInfoService.scala:654)
  at com.normation.rudder.services.nodes.NodeInfoServiceCachedImpl.checkUpToDate(NodeInfoService.scala:654)
  at com.normation.rudder.services.nodes.NodeInfoServiceCached.isUpToDate(NodeInfoService.scala:241)
  at com.normation.errors$IOResult$.effect(ZioCommons.scala:99)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:155)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at zio.ZIO$.bracketExit(ZIO.scala:1987)
  at zio.internal.FiberContext.evaluateNow(FiberContext.scala:527)
  at zio.ZIO.bracket_(ZIO.scala:244)
  at zio.ZIO.run(ZIO.scala:1450)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at com.normation.rudder.services.nodes.NodeInfoServiceCached.isUpToDate(NodeInfoService.scala:241)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at com.normation.zio$ZioRuntime$.effectBlocking(ZioCommons.scala:354)
  at zio.ZIO.bracket_(ZIO.scala:244)
  at zio.internal.FiberContext.evaluateNow(FiberContext.scala:523)
  at com.normation.rudder.services.nodes.NodeInfoServiceCached.withUpToDateCache(NodeInfoService.scala:396)
  at com.normation.errors$IOResult$.effect(ZioCommons.scala:99)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:155)
  at zio.internal.FiberContext$InterruptExit$.apply(FiberContext.scala:148)
  at zio.ZIO$.effectSuspendTotal(ZIO.scala:2260)
  at zio.ZIO$.bracketExit(ZIO.scala:1987)

Fiber:Id(1587444001876,1555202) was spawned by: <empty trace>
[2020-04-21 04:40:02] DEBUG scheduledJob - Dynamic group update in PT2M26.426S (started at 2020-04-21T04:37:35Z, ended at 2020-04-21T04:40:02Z)
[2020-04-21 04:40:02] ERROR scheduledJob - Error when updating dynamic group 'e91cbab0-299c-4d63-b8c5-649f9d7a3637' <- Exception caught during update process.
[2020-04-21 04:40:02] ERROR scheduledJob - Exception was:
java.util.NoSuchElementException: None.get
        at scala.None$.get(Option.scala:627)
        at scala.None$.get(Option.scala:626)
        at com.normation.rudder.services.nodes.NodeInfoServiceCached.$anonfun$withUpToDateCache$49(NodeInfoService.scala:416)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3368)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3365)
        at zio.internal.FiberContext.evaluateNow(FiberContext.scala:815)
        at zio.internal.FiberContext.$anonfun$evaluateLater$1(FiberContext.scala:687)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
[2020-04-21 04:40:02] ERROR scheduledJob - Error when updating dynamic group '1e608918-bb87-4c1c-812a-8b9486108718' <- Exception caught during update process.
[2020-04-21 04:40:02] ERROR scheduledJob - Exception was:
java.util.NoSuchElementException: None.get
        at scala.None$.get(Option.scala:627)
        at scala.None$.get(Option.scala:626)
        at com.normation.rudder.services.nodes.NodeInfoServiceCached.$anonfun$withUpToDateCache$49(NodeInfoService.scala:416)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3368)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3365)
        at zio.internal.FiberContext.evaluateNow(FiberContext.scala:815)
        at zio.internal.FiberContext.$anonfun$evaluateLater$1(FiberContext.scala:687)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
[2020-04-21 04:40:02] ERROR scheduledJob - Error when updating dynamic group '2418612c-6ccf-49b0-ac74-1ba17f6832f8' <- Exception caught during update process.
[2020-04-21 04:40:02] ERROR scheduledJob - Exception was:
java.util.NoSuchElementException: None.get
        at scala.None$.get(Option.scala:627)
        at scala.None$.get(Option.scala:626)
        at com.normation.rudder.services.nodes.NodeInfoServiceCached.$anonfun$withUpToDateCache$49(NodeInfoService.scala:416)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3368)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3365)
        at zio.internal.FiberContext.evaluateNow(FiberContext.scala:815)
        at zio.internal.FiberContext.$anonfun$evaluateLater$1(FiberContext.scala:687)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
[2020-04-21 04:40:02] ERROR scheduledJob - Error when updating dynamic group '42440453-b91f-4356-be38-108217838e66' <- Exception caught during update process.
[2020-04-21 04:40:02] ERROR scheduledJob - Exception was:
java.util.NoSuchElementException: None.get
        at scala.None$.get(Option.scala:627)
        at scala.None$.get(Option.scala:626)
        at com.normation.rudder.services.nodes.NodeInfoServiceCached.$anonfun$withUpToDateCache$49(NodeInfoService.scala:416)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3368)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3365)
        at zio.internal.FiberContext.evaluateNow(FiberContext.scala:815)
        at zio.internal.FiberContext.$anonfun$evaluateLater$1(FiberContext.scala:687)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
[2020-04-21 04:40:02] ERROR scheduledJob - Error when updating dynamic group 'cb9a59b6-61fe-43a8-9822-82a6a5c884ad' <- Exception caught during update process.
[2020-04-21 04:40:02] ERROR scheduledJob - Exception was:
java.util.NoSuchElementException: None.get
        at scala.None$.get(Option.scala:627)
        at scala.None$.get(Option.scala:626)
        at com.normation.rudder.services.nodes.NodeInfoServiceCached.$anonfun$withUpToDateCache$49(NodeInfoService.scala:416)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3368)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3365)
        at zio.internal.FiberContext.evaluateNow(FiberContext.scala:815)
        at zio.internal.FiberContext.$anonfun$evaluateLater$1(FiberContext.scala:687)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
[2020-04-21 04:40:02] ERROR scheduledJob - Error when updating dynamic group 'dd9e41c6-0b11-417d-8805-71352f42a33d' <- Exception caught during update process.
[2020-04-21 04:40:02] ERROR scheduledJob - Exception was:
java.util.NoSuchElementException: None.get
        at scala.None$.get(Option.scala:627)
        at scala.None$.get(Option.scala:626)
        at com.normation.rudder.services.nodes.NodeInfoServiceCached.$anonfun$withUpToDateCache$49(NodeInfoService.scala:416)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3368)
        at zio.ZIO$ZipRightFn.apply(ZIO.scala:3365)
        at zio.internal.FiberContext.evaluateNow(FiberContext.scala:815)
        at zio.internal.FiberContext.$anonfun$evaluateLater$1(FiberContext.scala:687)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)
[2020-04-21 04:40:02] ERROR scheduledJob - Error when updating dynamic group '6a982b36-f320-4c5a-8986-0b121de43c0a' <- Exception caught during update process.

and it goes on for every groups

Happens in 6.1, but likely to happen on 6.0 also

Subtasks 1 (0 open — 1 closed)

Bug #17221: Compilation issue on 6.1, class name changedReleasedFrançois ARMANDActions
Actions
Copy link
 #1

Updated by Vincent MEMBRÉ over 4 years ago

  • Status changed from New to In progress
  • Assignee set to Vincent MEMBRÉ
Actions
Copy link
 #2

Updated by Vincent MEMBRÉ over 4 years ago

  • Subject changed from error when updateing dynamic group to Concurrent access to node info cache cause exception to be thrown when accessing cache content
Actions
Copy link
 #3

Updated by Vincent MEMBRÉ over 4 years ago

  • Assignee changed from Vincent MEMBRÉ to François ARMAND
  • Pull Request set to https://github.com/Normation/rudder/pull/2910
Actions
Copy link
 #4

Updated by Vincent MEMBRÉ over 4 years ago

  • Status changed from In progress to Pending release
Actions
Copy link
 #5

Updated by Nicolas CHARLES over 4 years ago

  • Fix check changed from To do to Checked
Actions
Copy link
 #6

Updated by Vincent MEMBRÉ over 4 years ago

  • Status changed from Pending release to Released

This bug has been fixed in Rudder 6.0.6 which was released today.

Actions
Copy link

Also available in: Atom PDF