Operating System: All
Platform: All

karaf.log

Attachment karaf.log has been added with description: karaf.log

ConcurrentModificationException observed when installing odl features like odl-restconf which trigers installation of other dependent odl features.
you can reproduce it on latest Carbon SNAPSHOT, it is there for a while.
karaf 3.0.8

2017-01-24 22:04:02,935 | INFO | l for user karaf | DataObjectToJsonConverter | 338 - tech.pantheon.visibilitypackage.topologyutils.vp-topology-utils - 0.1.0.SNAPSHOT | Mapping service built
2017-01-24 22:04:02,951 | INFO | tAdminThread #19 | BlueprintBundleTracker | 176 - org.opendaylight.controller.blueprint - 0.6.0.SNAPSHOT | Blueprint container for bundle tech.pantheon.visibilitypackage.topologygenerator.vp-topology-generator-impl_0.1.0.SNAPSHOT [340] was successfully created
2017-01-24 22:04:02,953 | WARN | r - ConfigPusher | FeatureConfigPusher | 136 - config-persister-feature-adapter - 0.6.0.SNAPSHOT | Karaf featuresService.listInstalledFeatures() has thrown an exception, retry 0
java.util.ConcurrentModificationException
at java.util.HashMap$HashIterator.nextNode(HashMap.java:1437)[:1.8.0_111]
at java.util.HashMap$KeyIterator.next(HashMap.java:1461)[:1.8.0_111]
at java.util.AbstractCollection.toArray(AbstractCollection.java:196)[:1.8.0_111]
at org.apache.karaf.features.internal.FeaturesServiceImpl.listInstalledFeatures(FeaturesServiceImpl.java:840)[20:org.apache.karaf.features.core:3.0.8]
at Proxy6c30fc01_a81f_4a46_a011_c7ae5d9b78e7.listInstalledFeatures(Unknown Source)[:]
at org.opendaylight.controller.configpusherfeature.internal.FeatureConfigPusher.isInstalled(FeatureConfigPusher.java:97)[136:config-persister-feature-adapter:0.6.0.SNAPSHOT]
at org.opendaylight.controller.configpusherfeature.internal.FeatureConfigPusher.pushConfig(FeatureConfigPusher.java:78)[136:config-persister-feature-adapter:0.6.0.SNAPSHOT]
at org.opendaylight.controller.configpusherfeature.internal.FeatureConfigPusher.pushConfigs(FeatureConfigPusher.java:68)[136:config-persister-feature-adapter:0.6.0.SNAPSHOT]
at org.opendaylight.controller.configpusherfeature.internal.ConfigPushingRunnable.processFeatureEvent(ConfigPushingRunnable.java:65)[136:config-persister-feature-adapter:0.6.0.SNAPSHOT]
at org.opendaylight.controller.configpusherfeature.internal.ConfigPushingRunnable.run(ConfigPushingRunnable.java:47)[136:config-persister-feature-adapter:0.6.0.SNAPSHOT]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_111]
2017-01-24 22:04:06,837 | INFO | config-pusher | ConfigPusherImpl | 135 - org.opendaylight.controller.config-persister-impl - 0.6.0.SNAPSHOT | Pushing configuration snapshot 00-netty.xml(vp-all,vp-all)
2017-01-24 22:04:07,143 | INFO | config-pusher | ConfigPusherImpl | 135 - org.opendaylight.controller.config-persister-impl - 0.6.0.SNAPSHOT | Successfully pushed configuration snapshot 00-netty.xml(vp-all,vp-a

Just saw this as well (in netvirt/vpnservice/distribution/karaf on feature:install odl-netvirt-openstack; not related to actual feature being installed) .. not reliably reproducible, as these kinds of bugs typically go, of course.

I'm wondering if this is missing synchronization in Karaf's FeaturesServiceImpl or ODL's FeatureConfigPusher? If Karaf's FeaturesService is not meant to be thread safe, but if FeatureConfigPusher can run concurrently (for config of different bundles?), then we probably should ourselves synchronize when we use it? That's not that hard to do... I'll see if I can propose a Gerrit.

https://git.opendaylight.org/gerrit/#/c/53341/

In the 3.0.8 version of FeaturesServiceImpl, the 'installed' Map isn't synchronized. The master version at https://github.com/apache/karaf/blob/master/features/core/src/main/java/org/apache/karaf/features/internal/service/FeaturesServiceImpl.java appears to be correctly synchronized/thread-safe.

> the 3.0.8 version of FeaturesServiceImpl (...) The master version

OK, then let's say that properly resolving this bug depends on Karaf 4 upgrade ODLPARENT-23.

I'll try to adjust c/53341 with an ugly workaround hack in the mean time..

Oh... hang on, small confusion here.. the code in FeatureConfigPusher actually already does handle this with a retry logic! BUT:

(a) As three people independently reported this, not understanding that this WARN with the "retry 0" at the end does not actually indicate a problem, including current 2 controller committers not being aware of this, I would suggest that it is wrong to print a WARN log with a scary looking exception if it's "just" retrying - there should be no log (or only a DEBUG) - but an ERROR if it fails after retrying.

(b) On looking at this code more closely, I've also found a 2nd place where I guess this could happen and should be handled - in FeatureConfigPusher's pushConfig using featuresService.getFeature.

I'll change the Gerrit to do both (a) and (b) ...

This, from the current implementation, also seems a bit stupid:

private static final int MAX_RETRIES = 100;
private static final int RETRY_PAUSE_MILLIS = 1;

I'm going to change it to:

private static final int MAX_RETRIES = 10;
private static final int RETRY_PAUSE_MILLIS = 100;

> (b) On looking at this code more closely, I've also found a 2nd place where I > guess this could happen and should be handled - in FeatureConfigPusher's
> pushConfig using featuresService.getFeature.

I've ignored this, for now; we'll handle it some other time, maybe.

PS: Do we have a generic Retryer utility?

> PS: Do we have a generic Retryer utility?

org.opendaylight.genius.datastoreutils.TaskRetryLooper

I believe this was fixed a few months ago - also shouldn't be an issue with karaf 4.

> I believe this was fixed a few months ago

yes; https://git.opendaylight.org/gerrit/#/c/53341/ removed the confusing WARN log.