[jira] [Created] (KARAF-7450) Karaf failing to start bundle because of a dependency that is available

["Brent Shores (Jira)" <ji...@apache.org>]

Brent Shores created KARAF-7450:
-----------------------------------

             Summary: Karaf failing to start bundle because of a dependency that is available
                 Key: KARAF-7450
                 URL: https://issues.apache.org/jira/browse/KARAF-7450
             Project: Karaf
          Issue Type: Bug
          Components: karaf
    Affects Versions: 4.2.14, 4.4.0
         Environment: Windows 10 Pro

Karaf 4.2.14  ( I tried 4.4.0 as well )

32gb of memory

 

I do have two kar files that also load up, but the problem is with bundles in the system folder.  All of the problem bundles are part of system folder with everything else. 
            Reporter: Brent Shores
         Attachments: karaf.log.1

When I start up my karaf application, I'm getting a lot of bundles that initially go into a GracePeriod state, and then move from there to Failure after they timeout.  When I start following the dependency chain, I got down to the top-level one and it had a dependency on another bundle that was successfully loaded up.  For my example, the bundle I'm looking at is this: ( from the list command)

 
74 | Failure |  82 | 1.5.1               | inventorysrvc-ext
 
Then I look at the diagnostic for it:
Run "diag 74"
 
karaf@root()> diag 74
inventorysrvc-ext (74)
----------------------
Status: Failure
Blueprint
6/6/22 8:40 AM
Exception:
null
java.util.concurrent.TimeoutException
        at org.apache.aries.blueprint.container.BlueprintContainerImpl$1.run(BlueprintContainerImpl.java:393)
        at org.apache.aries.blueprint.utils.threading.impl.DiscardableRunnable.run(DiscardableRunnable.java:45)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        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)
 
Missing dependencies:
(objectClass=com.toshibacommerce.service.inventorysrvc.api.IInventoryHelper)
Declarative Services
CdiOsgi
So it's missing IInventoryHelper.   Except looking at my code, that IInventoryHelper is being added inside my inventorysrvc-helper bundle.  Here's the blueprint for that:
<blueprint xmlns="http://www.osgi.org/xmlns/blueprint/v1.0.0"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://www.osgi.org/xmlns/blueprint/v1.0.0 http://www.osgi.org/xmlns/blueprint/v1.0.0/blueprint.xsd">
<!-- registering inventory helper services -->
<bean id="invHelper"
class="com.toshibacommerce.service.inventorysrvc.helper.InventoryHelper">
<property name="confProperty" ref="confProperty" />
</bean>
<service ref="invHelper"
interface="com.toshibacommerce.service.inventorysrvc.api.IInventoryHelper" />
<reference id="confProperty"
interface="com.toshibacommerce.commons.props.api.IConfigProperty" />
</blueprint>
 
This bundle status:
75 | Active  |  80 | 1.5.1               | inventorysrvc-helper
 
So I think I'm just in a bad order and it failed to load, so I restart 74, because I know it's one missing dependency is available now.
 
karaf@root()> restart 74
 
And it does the same GracePeriod or Failure with the same timeout exception.  No other useful errors even with log level turned up.  Only error in logs is:


There error shown in the logs at the initial startup is:
[ERROR] 06/06/2022 10:52:16.074 [Blueprint Extender: 1] BlueprintContainerImpl[396] - Unable to start container for blueprint bundle inventorysrvc-ext/1.5.1 due to unresolved dependencies [(objectClass=com.toshibacommerce.service.inventorysrvc.api.IInventoryHelper)]
java.util.concurrent.TimeoutException: null
at org.apache.aries.blueprint.container.BlueprintContainerImpl$1.run(BlueprintContainerImpl.java:393) [!/:1.10.3]
at org.apache.aries.blueprint.utils.threading.impl.DiscardableRunnable.run(DiscardableRunnable.java:45) [!/:1.10.3]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0-292]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0-292]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0-292]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0-292]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0-292]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0-292]
at java.lang.Thread.run(Thread.java:748) 
[?:1.8.0-292]
 
Which doesn't tell me much.  When I attempt to start the bundle, nothing happens.  I'm hoping there is some sort of logging I can turn on or something to see more info on the missing dependency and why it thinks it's not there when it is.
 
I'm attaching the full log file.  Ignore anything before 8:35am.  Also there are a bunch of errors from a cloudforwarder services.  That's just because it can't reach it's rest service.  Not an issue.
 
When I did a restart it showed slightly different in logs:
 
[INFO ] 06/07/2022 07:14:59.780 [pipe-restart 74] BlueprintExtender[358] - Destroying container for blueprint bundle inventorysrvc-ext/1.5.1
[INFO ] 06/07/2022 07:14:59.824 [pipe-restart 74] Activator[45] - Stopping the Inventorysrvc-ext bundle
[INFO ] 06/07/2022 07:14:59.824 [pipe-restart 74] Activator[36] - Starting the Inventorysrvc-ext bundle
[INFO ] 06/07/2022 07:14:59.840 [pipe-restart 74] BlueprintContainerImpl[408] - Blueprint bundle inventorysrvc-ext/1.5.1 is waiting for dependencies [(objectClass=com.toshibacommerce.service.inventorysrvc.api.IInventoryHelper)]
[INFO ] 06/07/2022 07:14:59.918 [pipe-restart 74] CommandExtension[108] - Command registration delayed for bundle inventorysrvc-ext/1.5.1. Missing service: 
[com.toshibacommerce.service.inventorysrvc.ext.trigger.IInventoryTrigger, com.toshibacommerce.service.inventorysrvc.ext.cfg.IConfig]
 
Both of those dependencies it's mentioning are actually in the inventorysrvc-ext bundle, so now it's failing to load itself?  
 
Yeah, so that's my issue.  I have the dependencies in place, but Karaf won't load my bundle.  If I do a "feature:install transaction", which forces it to unload and reload a bunch of things, it will come up.
 
My theory is a race condition going on somehow.  On faster machines, it seems to work more often, slower machines, it's more likely to get hung here.  If I wipe the data directory and restart it might come up, might not.  If I just restart without deleting data, it fails most of the time.



--
This message was sent by Atlassian Jira
(v8.20.7#820007)