Grzegorz Grzybek created KARAF-7126:
---------------------------------------
Summary: State overwrite when installing more features at once
Key: KARAF-7126
URL: https://issues.apache.org/jira/browse/KARAF-7126
Project: Karaf
Issue Type: Bug
Affects Versions: 4.3.1, 4.2.11
Reporter: Grzegorz Grzybek
Assignee: Grzegorz Grzybek
Fix For: 4.2.12, 4.3.2
I had a case, where (which is not recommended) two feature XML files were
dropped into {{deploy/}} directory.
_Often_ (but not always) one of the features was not marked as "Started" - and
it happened in random order.
It can be reproduced with {{simple1.xml}} file:
{code:xml}
<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<features xmlns="http://karaf.apache.org/xmlns/features/v1.3.0"; name="simple1">
<feature name="simple1" version="0.0.1" install="auto">
<bundle start-level="80"
start="true">mvn:commons-io/commons-io/2.8.0</bundle>
</feature>
</features>
{code}
and {{simple2.xml}}:
{code:xml}
<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<features xmlns="http://karaf.apache.org/xmlns/features/v1.3.0"; name="simple2">
<feature name="simple2" version="0.0.1" install="auto">
<bundle start-level="80"
start="true">mvn:commons-collections/commons-collections/3.2.2</bundle>
</feature>
</features>
{code}
dropped at the same time to {{deploy/}} directory.
Here's my investigation:
1. deploy two files
2. these artifacts are processed in single fileinstall thread:
{noformat}
0 = {org.apache.felix.fileinstall.internal.Artifact@11682}
path: java.io.File = {java.io.File@11683} "/data/karaf/deploy/simple1.xml"
jaredDirectory: java.io.File = {java.io.File@11683}
"/data/karaf/deploy/simple1.xml"
jaredUrl: java.net.URL = {java.net.URL@11703}
"file:/data/karaf/deploy/simple1.xml"
listener: org.apache.felix.fileinstall.ArtifactListener =
{org.apache.karaf.deployer.features.FeatureDeploymentListener@11698}
transformedUrl: java.net.URL = {java.net.URL@11646}
"feature:file:/data/karaf/deploy/simple1.xml"
transformed: java.io.File = null
bundleId: long = -1 (0xFFFFFFFFFFFFFFFF)
checksum: long = 1818582559 (0x6C655E1F)
1 = {org.apache.felix.fileinstall.internal.Artifact@11694}
path: java.io.File = {java.io.File@11696} "/data/karaf/deploy/simple2.xml"
jaredDirectory: java.io.File = {java.io.File@11696}
"/data/karaf/deploy/simple2.xml"
jaredUrl: java.net.URL = {java.net.URL@11697}
"file:/data/karaf/deploy/simple2.xml"
listener: org.apache.felix.fileinstall.ArtifactListener =
{org.apache.karaf.deployer.features.FeatureDeploymentListener@11698}
transformedUrl: java.net.URL = {java.net.URL@11699}
"feature:file:/data/karaf/deploy/simple2.xml"
transformed: java.io.File = null
bundleId: long = -1 (0xFFFFFFFFFFFFFFFF)
checksum: long = 3138423735 (0xBB108BB7)
3. single instance of org.apache.karaf.deployer.features.FeatureURLHandler has
its org.apache.karaf.deployer.features.FeatureURLHandler#featureXmlURL set to
file:/data/karaf/deploy/simple1.xml
stack trace:
{noformat}
"fileinstall-/data/karaf/deploy@11585" daemon prio=5 tid=0x2e nid=NA runnable
java.lang.Thread.State: RUNNABLE
at
org.apache.karaf.deployer.features.FeatureURLHandler.openConnection(FeatureURLHandler.java:56)
at
org.apache.felix.framework.URLHandlersStreamHandlerProxy.openConnection(URLHandlersStreamHandlerProxy.java:271)
at java.net.URL.openConnection(URL.java:1002)
at java.net.URL.openStream(URL.java:1068)
at
org.apache.felix.fileinstall.internal.DirectoryWatcher.install(DirectoryWatcher.java:962)
at
org.apache.felix.fileinstall.internal.DirectoryWatcher.install(DirectoryWatcher.java:884)
at
org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:489)
at
org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365)
at
org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316)
{noformat}
4. in
org.apache.felix.fileinstall.internal.DirectoryWatcher#installOrUpdateBundle,
simple1 is processed
5. log message:
{noformat}
Installing bundle simple1.xml / 0.0.0
{noformat}
6. org.osgi.framework.BundleContext#installBundle() for simple1
7. featureXmlURL is set to simple2.xml
8. log message:
{noformat}
Installing bundle simple2.xml / 0.0.0
{noformat}
9. org.osgi.framework.BundleContext#installBundle() for simple2
Now:
{noformat}
240 │ Installed │ 80 │ 0.0.0 │
feature:file:/data/karaf/deploy/simple1.xml
241 │ Installed │ 80 │ 0.0.0 │
feature:file:/data/karaf/deploy/simple2.xml
{noformat}
10. Of course
org.apache.felix.fileinstall.internal.DirectoryWatcher#doProcess() uses
HashMaps... that's why bundle2 may be started earlier
11. org.apache.felix.fileinstall.internal.FileInstall#refresh() is called for
the two bundles in random order - but they're still in INSTALLED state
12. org.apache.felix.fileinstall.internal.DirectoryWatcher#startBundles() is
called
13. org.osgi.framework.Bundle#start(int) is called for each bundle and the
event is caught by:
{noformat}
"FelixDispatchQueue@11772" prio=5 tid=0xd nid=NA runnable
java.lang.Thread.State: RUNNABLE
at
org.apache.karaf.deployer.features.FeatureDeploymentListener.bundleChanged(FeatureDeploymentListener.java:186)
- locked <0x2db2> (a
org.apache.karaf.deployer.features.FeatureDeploymentListener)
at
org.apache.felix.framework.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:915)
at
org.apache.felix.framework.EventDispatcher.fireEventImmediately(EventDispatcher.java:834)
at
org.apache.felix.framework.EventDispatcher.run(EventDispatcher.java:1147)
at
org.apache.felix.framework.EventDispatcher.access$000(EventDispatcher.java:54)
at
org.apache.felix.framework.EventDispatcher$1.run(EventDispatcher.java:102)
at java.lang.Thread.run(Thread.java:748)
{noformat}
14. eventually two tasks are correctly passed to single featuresService pool
the first one (running). It has these vars reachable:
{noformat}
this =
{org.apache.karaf.features.internal.service.FeaturesServiceImpl$$Lambda$108.830131376@12778}
arg$1: org.apache.karaf.features.internal.service.FeaturesServiceImpl =
{org.apache.karaf.features.internal.service.FeaturesServiceImpl@12631}
arg$2: java.util.Set = {java.util.HashSet@12648} size = 1
arg$3: java.util.Map = {java.util.HashMap@12643} size = 1
arg$4: java.util.Map = {java.util.Collections$EmptyMap@12644} size = 0
arg$5: org.apache.karaf.features.internal.service.State =
{org.apache.karaf.features.internal.service.State@12645}
arg$6: java.util.Map = {java.util.HashMap@12646} size = 621
arg$7: java.util.EnumSet = {java.util.RegularEnumSet@12647} size = 0
arg$8: java.lang.String = null
{noformat}
the second one (waiting). It has these vars reachable:
{noformat}
callable: java.util.concurrent.Callable =
{org.apache.karaf.features.internal.service.FeaturesServiceImpl$$Lambda$108.830131376@12760}
arg$1: org.apache.karaf.features.internal.service.FeaturesServiceImpl =
{org.apache.karaf.features.internal.service.FeaturesServiceImpl@12631}
arg$2: java.util.Set = {java.util.HashSet@12663} size = 1
arg$3: java.util.Map = {java.util.HashMap@12659} size = 1
arg$4: java.util.Map = {java.util.Collections$EmptyMap@12644} size = 0
arg$5: org.apache.karaf.features.internal.service.State =
{org.apache.karaf.features.internal.service.State@12660}
arg$6: java.util.Map = {java.util.HashMap@12661} size = 622
arg$7: java.util.EnumSet = {java.util.RegularEnumSet@12662} size = 0
arg$8: java.lang.String = null
{noformat}
The only important difference is that 2nd task already has larger map of
features.
State of the running task:
{noformat}
state = {org.apache.karaf.features.internal.service.State@12645}
bootDone: java.util.concurrent.atomic.AtomicBoolean =
{java.util.concurrent.atomic.AtomicBoolean@17577} "true"
repositories: java.util.Set = {java.util.TreeSet@17578} size = 13
requirements: java.util.Map = {java.util.HashMap@17579} size = 1
installedFeatures: java.util.Map = {java.util.HashMap@17580} size = 1
stateFeatures: java.util.Map = {java.util.HashMap@17581} size = 1
managedBundles: java.util.Map = {java.util.HashMap@17582} size = 1
bundleChecksums: java.util.Map = {java.util.HashMap@17583} size = 0
{noformat}
State of the waiting task:
{noformat}
arg$5: org.apache.karaf.features.internal.service.State =
{org.apache.karaf.features.internal.service.State@12660}
bootDone: java.util.concurrent.atomic.AtomicBoolean =
{java.util.concurrent.atomic.AtomicBoolean@17644} "true"
repositories: java.util.Set = {java.util.TreeSet@17645} size = 14
requirements: java.util.Map = {java.util.HashMap@17646} size = 1
installedFeatures: java.util.Map = {java.util.HashMap@17647} size = 1
stateFeatures: java.util.Map = {java.util.HashMap@17648} size = 1
managedBundles: java.util.Map = {java.util.HashMap@17649} size = 1
bundleChecksums: java.util.Map = {java.util.HashMap@17650} size = 0
{noformat}
15. Even at first line of
org.apache.karaf.features.internal.service.FeaturesServiceImpl#doProvision(),
feature:list already gives me:
{noformat}
karaf@root()> feature:list | grep simple
simple1 │ 0.0.1 │
│ Uninstalled │ simple1 │
simple2 │ 0.0.1 │
│ Uninstalled │ simple2 │
{noformat}
16. When 2nd task runs, there are two State instances:
the state attached to 2nd task just started:
{noformat}
State@12660
bootDone: java.util.concurrent.atomic.AtomicBoolean =
{java.util.concurrent.atomic.AtomicBoolean@17644} "true"
repositories: java.util.Set = {java.util.TreeSet@17645} size = 14
requirements: java.util.Map = {java.util.HashMap@17646} size = 1
installedFeatures: java.util.Map = {java.util.HashMap@17647} size = 1
"root" -> {java.util.HashSet@52251} size = 120
stateFeatures: java.util.Map = {java.util.HashMap@17648} size = 1
managedBundles: java.util.Map = {java.util.HashMap@17649} size = 1
bundleChecksums: java.util.Map = {java.util.HashMap@17650} size = 0
{noformat}
the state copied to features service after first task finishes - in this state,
simple1 is already installed
{noformat}
State@12846
bootDone: java.util.concurrent.atomic.AtomicBoolean =
{java.util.concurrent.atomic.AtomicBoolean@52374} "true"
repositories: java.util.Set = {java.util.TreeSet@17833} size = 14
requirements: java.util.Map = {java.util.HashMap@52375} size = 1
installedFeatures: java.util.Map = {java.util.HashMap@52376} size = 1
"root" -> {java.util.HashSet@52384} size = 121
stateFeatures: java.util.Map = {java.util.HashMap@52377} size = 1
managedBundles: java.util.Map = {java.util.HashMap@52378} size = 1
bundleChecksums: java.util.Map = {java.util.HashMap@52379} size = 0
{noformat}
17. so far, so good:
{noformat}
karaf@root()> feature:list | grep simple
simple1 │ 0.0.1 │
│ Uninstalled │ simple1 │
simple2 │ 0.0.1 │ x
│ Started │ simple2 │
{noformat}
18. (different debugger run, so addresses have changed) here's how state after
first feature installation is used to replace existing state:
existing:
{noformat}
this.state = {org.apache.karaf.features.internal.service.State@39249}
bootDone: java.util.concurrent.atomic.AtomicBoolean =
{java.util.concurrent.atomic.AtomicBoolean@39250} "true"
repositories: java.util.Set = {java.util.TreeSet@39257} size = 14
requirements: java.util.Map = {java.util.HashMap@39258} size = 1
installedFeatures: java.util.Map = {java.util.HashMap@39259} size = 1
"root" -> {java.util.HashSet@39266} size = 120
stateFeatures: java.util.Map = {java.util.HashMap@39260} size = 1
managedBundles: java.util.Map = {java.util.HashMap@39261} size = 1
bundleChecksums: java.util.Map = {java.util.HashMap@39262} size = 0
{noformat}
new:
{noformat}
state = {org.apache.karaf.features.internal.service.State@39248}
bootDone: java.util.concurrent.atomic.AtomicBoolean =
{java.util.concurrent.atomic.AtomicBoolean@39251} "true"
repositories: java.util.Set = {java.util.TreeSet@39267} size = 14
requirements: java.util.Map = {java.util.HashMap@39268} size = 1
installedFeatures: java.util.Map = {java.util.HashMap@39269} size = 1
"root" -> {java.util.HashSet@39276} size = 121
stateFeatures: java.util.Map = {java.util.HashMap@39270} size = 1
managedBundles: java.util.Map = {java.util.HashMap@39271} size = 1
bundleChecksums: java.util.Map = {java.util.HashMap@39272} size = 0
{noformat}
19. and second feature installation:
existing (simple1 is installed in `installedFeatures`):
{noformat}
this.state = {org.apache.karaf.features.internal.service.State@39249}
bootDone: java.util.concurrent.atomic.AtomicBoolean =
{java.util.concurrent.atomic.AtomicBoolean@39250} "true"
repositories: java.util.Set = {java.util.TreeSet@39257} size = 14
requirements: java.util.Map = {java.util.HashMap@39258} size = 1
installedFeatures: java.util.Map = {java.util.HashMap@39259} size = 1
"root" -> {java.util.HashSet@44230} size = 121
stateFeatures: java.util.Map = {java.util.HashMap@39260} size = 1
managedBundles: java.util.Map = {java.util.HashMap@39261} size = 1
bundleChecksums: java.util.Map = {java.util.HashMap@39262} size = 0
{noformat}
new (simple2 is installed in `installedFeatures`):
{noformat}
state = {org.apache.karaf.features.internal.service.State@44226}
bootDone: java.util.concurrent.atomic.AtomicBoolean =
{java.util.concurrent.atomic.AtomicBoolean@44227} "true"
repositories: java.util.Set = {java.util.TreeSet@44231} size = 14
requirements: java.util.Map = {java.util.HashMap@44232} size = 1
installedFeatures: java.util.Map = {java.util.HashMap@44233} size = 1
"root" -> {java.util.HashSet@44240} size = 121
stateFeatures: java.util.Map = {java.util.HashMap@44234} size = 1
managedBundles: java.util.Map = {java.util.HashMap@44235} size = 1
bundleChecksums: java.util.Map = {java.util.HashMap@44236} size = 0
{noformat}
And here's the problem - scheduled provisioning tasks capture some State and
the 2nd task which runs doesn't update its state after first task finishes.
This is reproducible also with simple:
{noformat}
karaf@root()> feature:install simple1 & feature:install simple2
[1] background feature:install simple1
[1] done feature:install simple1
karaf@root()>
karaf@root()> feature:list|grep simple
simple2 │ 0.0.1 │ x
│ Started │ simple2 │
simple1 │ 0.0.1 │
│ Uninstalled │ simple1 │
{noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
