|
Attachment karafagain.zip has been added with description: karaf log
|
|
Attachment karaf.zip has been added with description: Another karaf log experiencing this issue
|
|
It seems like an issue in binding generator, hence moved to md-sal.
|
|
Hi
what do you mean by "close to stable" ?
Since issue occurs only sometimes, I decrease severity to MAJOR.
|
|
It looks like we came across this issue in the past
https://lists.opendaylight.org/pipermail/sfc-dev/2015-November/002344.html
https://git.opendaylight.org/gerrit/#/c/18820
investigating ...
|
|
Synced from stable boron at 15/12/2016.
I think it is critical because when it happens, the workflow completely fails.
The fact that it is a race bug, which is not deterministic, is a stronger reason to fix that, because any mechanism that will try to workaround it until fixed, can't be actually verified.
Is there a theoretical workaround?
Maybe retrying the serialization can help ? Add a sleep before ? I really don't know what is the possible root cause, so it would really help to get some directions from you guys.
|
|
Now I got the same exception while calling tx.merge in a write transaction. It made me think that maybe the concurrent operations i'm doing are:
- Serializing a DataObject to JSON
- Merging a write transaction with the same type of DataObject into MD-SAL.
Can this explain the failure?
If it does, will it happen only in the first time serializing the object?
I'm attaching the log of the new failure
|
|
Attachment karaf.log.gz has been added with description: Karaf log that fails in merge tx
|
|
So as a workaround I added a Thread.sleep of 500 millis and retried the operation, and it actually fixed the problem.
|
|
Okay so apparently I can't apply this workaround, because the frozen class issue can stem from places that are not in my control:
com.google.common.util.concurrent.UncheckedExecutionException: com.google.common.util.concurrent.UncheckedExecutionException: java.lang.RuntimeException: org.opendaylight.yang.gen.v1.urn.opendaylight.netvirt.ela
n.rev150602.elan.interfaces.ElanInterface$StreamWriter: frozen class (cannot edit)
at com.google.common.cache.LocalCache$Segment.get(LocalCache.java:2203)[38:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache.get(LocalCache.java:3937)[38:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache.getOrLoad(LocalCache.java:3941)[38:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$LocalLoadingCache.get(LocalCache.java:4824)[38:com.google.guava:18.0.0]
at com.google.common.cache.LocalCache$LocalLoadingCache.getUnchecked(LocalCache.java:4830)[38:com.google.guava:18.0.0]
at org.opendaylight.yangtools.binding.data.codec.impl.BindingNormalizedNodeCodecRegistry.getSerializer(BindingNormalizedNodeCodecRegistry.java:72)[92:org.opendaylight.mdsal.binding-dom-codec:0.9.2.SNAPSH
OT]
at org.opendaylight.yangtools.binding.data.codec.impl.BindingNormalizedNodeCodecRegistry.toNormalizedNode(BindingNormalizedNodeCodecRegistry.java:106)[92:org.opendaylight.mdsal.binding-dom-codec:0.9.2.SN
APSHOT]
at org.opendaylight.controller.md.sal.binding.impl.BindingToNormalizedNodeCodec.toNormalizedNode(BindingToNormalizedNodeCodec.java:132)[146:org.opendaylight.controller.sal-binding-broker-impl:1.4.2.SNAPS
HOT]
at org.opendaylight.controller.md.sal.binding.impl.AbstractWriteTransaction.put(AbstractWriteTransaction.java:39)[146:org.opendaylight.controller.sal-binding-broker-impl:1.4.2.SNAPSHOT]
at org.opendaylight.genius.mdsalutil.MDSALUtil.syncWrite(MDSALUtil.java:521)[281:org.opendaylight.genius.mdsalutil-api:0.1.2.SNAPSHOT]
at org.opendaylight.netvirt.elan.internal.ElanServiceProvider.addElanInterface(ElanServiceProvider.java:271)[325:org.opendaylight.netvirt.elanmanager-impl:0.3.2.SNAPSHOT]
at org.opendaylight.netvirt.elan.internal.ElanServiceProvider.createExternalElanNetwork(ElanServiceProvider.java:489)[325:org.opendaylight.netvirt.elanmanager-impl:0.3.2.SNAPSHOT]
at org.opendaylight.netvirt.elan.internal.ElanServiceProvider.lambda$createExternalElanNetworks$0(ElanServiceProvider.java:469)[325:org.opendaylight.netvirt.elanmanager-impl:0.3.2.SNAPSHOT]
at org.opendaylight.netvirt.elan.internal.ElanServiceProvider.handleExternalElanNetworks(ElanServiceProvider.java:702)[325:org.opendaylight.netvirt.elanmanager-impl:0.3.2.SNAPSHOT]
at org.opendaylight.netvirt.elan.internal.ElanServiceProvider.createExternalElanNetworks(ElanServiceProvider.java:468)[325:org.opendaylight.netvirt.elanmanager-impl:0.3.2.SNAPSHOT]
at org.opendaylight.netvirt.elan.internal.ElanOvsdbNodeListener.add(ElanOvsdbNodeListener.java:97)[325:org.opendaylight.netvirt.elanmanager-impl:0.3.2.SNAPSHOT]
at org.opendaylight.netvirt.elan.internal.ElanOvsdbNodeListener.add(ElanOvsdbNodeListener.java:30)[325:org.opendaylight.netvirt.elanmanager-impl:0.3.2.SNAPSHOT]
at org.opendaylight.genius.mdsalutil.AbstractDataChangeListener.createData(AbstractDataChangeListener.java:68)[281:org.opendaylight.genius.mdsalutil-api:0.1.2.SNAPSHOT]
at org.opendaylight.genius.mdsalutil.AbstractDataChangeListener.onDataChanged(AbstractDataChangeListener.java:54)[281:org.opendaylight.genius.mdsalutil-api:0.1.2.SNAPSHOT]
at org.opendaylight.controller.md.sal.binding.impl.AbstractForwardedDataBroker$TranslatingDataChangeInvoker.onDataChanged(AbstractForwardedDataBroker.java:143)[146:org.opendaylight.controller.sal-binding-broker-impl:1.4.2.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.DataChangeListener.dataChanged(DataChangeListener.java:71)[176:org.opendaylight.controller.sal-distributed-datastore:1.4.2.SNAPSHOT]
at org.opendaylight.controller.cluster.datastore.DataChangeListener.handleReceive(DataChangeListener.java:43)[176:org.opendaylight.controller.sal-distributed-datastore:1.4.2.SNAPSHOT]
at org.opendaylight.controller.cluster.common.actor.AbstractUntypedActor.onReceive(AbstractUntypedActor.java:26)[170:org.opendaylight.controller.sal-clustering-commons:1.4.2.SNAPSHOT]
at akka.actor.UntypedActor$$anonfun$receive$1.applyOrElse(UntypedActor.scala:165)[158:com.typesafe.akka.actor:2.4.7]
at akka.actor.Actor$class.aroundReceive(Actor.scala:484)[158:com.typesafe.akka.actor:2.4.7]
at akka.actor.UntypedActor.aroundReceive(UntypedActor.scala:95)[158:com.typesafe.akka.actor:2.4.7]
at akka.actor.ActorCell.receiveMessage(ActorCell.scala:526)[158:com.typesafe.akka.actor:2.4.7]
at akka.actor.ActorCell.invoke(ActorCell.scala:495)[158:com.typesafe.akka.actor:2.4.7]
at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257)[158:com.typesafe.akka.actor:2.4.7]
at akka.dispatch.Mailbox.run(Mailbox.scala:224)[158:com.typesafe.akka.actor:2.4.7]
at akka.dispatch.Mailbox.exec(Mailbox.scala:234)[158:com.typesafe.akka.actor:2.4.7]
at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)[154:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)[154:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)[154:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)[154:org.scala-lang.scala-library:2.11.8.v20160304-115712-1706a37eb8]
Caused by: com.google.common.util.concurrent.UncheckedExecutionException: java.lang.RuntimeException: org.opendaylight.yang.gen.v1.urn.opendaylight.netvirt.elan.rev150602.elan.interfaces.ElanInterface$StreamWriter: frozen class (cannot edit)
|
|
I suspect we need to move away from javassist to get rid of this issue. I suspect this happens because the class loaders are not completely cleaned up and we end up with untracked codec classes.
|
|
We've hit this one again, and apparently we (not myself but aswins JankiChhatbar smalleni ?) can now fairly reliably reproduce this...
MDSAL maintainers rovarga tpantelis martin.ciglan can you help with this?
Otherwise I guess I'll have to dig into this code to see if I can make any sense of this... 
|
|
FTR: As was discussed in MDSAL-230, following MDSAL-200 the stack trace is now .mdsal. instead of .yangtools. but this is the very same issue, here's a current stack trace, from our https://bugzilla.redhat.com/show_bug.cgi?id=1573273 :
|
|
> Otherwise I guess I'll have to dig into this code to see if I can make any sense of this...
This having been a purely rhetorical  Q, I now at least understand what can cause these Princess Elsa of Arendelle (frozen) situations:
@Test
public void testMDSAL_213() throws NotFoundException, CannotCompileException {
JavassistUtils javassistUtils = JavassistUtils.forClassPool(ClassPool.getDefault());
Class<String> type = String.class;
CtClass poolClass = javassistUtils.instantiatePrototype(type.getName(), "Something$StreamWriter", cls -> { });
@SuppressWarnings({ "unchecked", "unused" })
Class<? extends DataObjectSerializerImplementation> javaClass = poolClass.toClass(type.getClassLoader(), type.getProtectionDomain());
javassistUtils.instantiatePrototype(type.getName(), "Something$StreamWriter", cls -> { });
}
Above is inspired from the real code in org.opendaylight.mdsal.binding.dom.codec.gen.impl.AbstractStreamWriterGenerator but simplified a bit (and we use String as the type instead of the real DataObjectSerializerPrototype just because that is not available in mdsal-binding-dom-codec). If we copy/paste that e.g. into org.opendaylight.mdsal.binding.generator.util.JavassistUtilsTest, then the 2nd instantiatePrototype() indeed causes:
java.lang.RuntimeException: Something$StreamWriter: frozen class (cannot edit)
But if, and only if, the poolClass.toClass() already happened! So this smells of some concurrency problem - we may be creating the $StreamWriter in parallel? The fact that this problem is only seen in cluster load tests, but not eay gone standard CSITs supports that hypothesis. The trouble is... the way I currently understand the code in AbstractStreamWriterGenerator it SHOULD be concurrency/thread safe? But clearly it's not, as we are hitting this problem (and can reproduce it) - so what am I missing? If not found, we could perhaps also build a dumb band aid fix... the way I understand things, that 2nd new $StreamWriter should be the same as the original one? So... we could cheat, and brush the frozen yogurt RuntimeException under the carpet, IFF we meanwhile have the class in the cache? I'll propose something like that - for discussion. I'll also add some additional logging to see if perhaps that could help to make more sense of what is really going on here.
|
|
I think this boils down to classloader vs. classpool vs. cache lifecycle. I do not believe we can just sweep it under the carpet – for that you need to be sure you are sweeping, not smearing ...
|
|
> I think this boils down to classloader vs. classpool vs. cache lifecycle.
right... so the ClassPool (currently) ultimately used in AbstractStreamWriterGenerator is fixed, unless I'm completely mistaken, it's the private static final JavassistUtils JAVASSIST = JavassistUtils.forClassPool(ClassPool.getDefault()); from the BindingToNormalizedNodeCodecFactory?
the classloader vs. cache lifecycle is a little unclear to me so far, but one of the changes I've raised today under this JIRA (see above) adds more (debug) logging; if I can get that to run on where we can apparently reproduce this fairly reliably, perhaps we'll learn more.
|
|
Just for the record, this looks funky, but I don't thinks is our problem here, because we do not evict, at least not programmatically (but GC?):
* https://softwaremill.com/race-condition-cache-guava-caffeine/
but we DO have weak Class keys - one of my Gerrits today proposes to remove them.
|
|
While we are using weak keys, it is on Class objects – which means that a GC-induced invalidation of the key simply cannot happen while we are using it for lookup.
|
|
jluhrsen meanwhile has also hit this in NETVIRT-1089, and will try to provide us the new debug logs I recently added.
I've just stumbled upon CONTROLLER-1832, which could be related / causing this... TBC if THE or A cause.
|
|
CONTROLLER-1834 has something else which seems vaguely related - not claiming / no proof (yet) it's causing this, but at least worth noting.
|
|
jluhrsen's NETVIRT-1089 is no longer able to reproduce this after CONTROLLER-1832
|
|
FTR: The additional DEBUG logigng for this (c/71890) went into Oxygen SR2 (not only SR3; which CONTROLLER-1834 and CONTROLLER-1832 will).
|
Generated at Wed Feb 07 20:09:04 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.
karaf.log.gz
karaf.zip