attributeWhenReady hung, even after sensor set

[aledsage]

An appserver using attributeWhenReady is waiting for a DB's "url.mapped" attribute to be set. However, after 24 minutes I noticed that the value had already been set, yet the task was still waiting.

The yaml is:
$brooklyn:formatString("jdbc:%s%s", component("db").attributeWhenReady("url.mapped"), "tradedb")

The DB entity has:
url.mapped mysql://37.58.96.163:49327/

The appserver's task has:

{
"id": "AlruMJA6",
"displayName": "retrieving sensor url.mapped from DB",
"description": "",
"entityId": "X4ulV4kP",
"entityDisplayName": "WebsphereLiberty:X4ul",
"tags": [
    "attributeWhenReady",
    "Wrapped[contextEntity:WebsphereLibertyImpl{id=X4ulV4kP}]"
],
"submitTimeUtc": 1399069511307,
"startTimeUtc": 1399069511307,
"endTimeUtc": null,
"currentStatus": "In progress",
"result": null,
"isError": false,
"isCancelled": false,
"children": [],
"submittedByTask": {
    "link": "/v1/activities/d2ju1l4w",
    "metadata": {
        "id": "d2ju1l4w",
        "taskName": "formatting 'jdbc:%s%s' with 1 task",
        "entityId": "X4ulV4kP",
        "entityDisplayName": "WebsphereLiberty:X4ul"
    }
},
"blockingDetails": "Waiting for ready from MySqlNodeImpl{id=Co35ElLk} Sensor: url.mapped (java.lang.Object) (subscription)",
"detailedStatus": "Waiting for ready from MySqlNodeImpl{id=Co35ElLk} Sensor: url.mapped (java.lang.Object) (subscription)

Task[retrieving sensor url.mapped from DB [attributeWhenReady, Wrapped[contextEntity:WebsphereLibertyImpl{id=X4ulV4kP}]]; AlruMJA6]
Submitted by Task[formatting 'jdbc:%s%s' with 1 task [Wrapped[contextEntity:WebsphereLibertyImpl{id=X4ulV4kP}]]; d2ju1l4w]

In progress, thread waiting (notify) on java.util.concurrent.Semaphore$NonfairSync@70224c05
At: brooklyn.event.basic.DependentConfiguration.waitInTaskForAttributeReady(DependentConfiguration.java:178)
brooklyn.event.basic.DependentConfiguration$Builder$1.call(DependentConfiguration.java:441)
brooklyn.util.task.BasicExecutionManager$3.call(BasicExecutionManager.java:352)",
"streams": {},
"links": {
    "self": "/v1/activities/AlruMJA6",
    "children": "/v1/activities/AlruMJA6/children",
    "entity": "/v1/applications/vUX7IzUb/entities/X4ulV4kP"
},
"blockingTask": TYPEOF: undefined
}

The jstack output shows:

"brooklyn-execmanager-RkebfZSD-199" daemon prio=5 tid=7fe705d90800 nid=0x11fa32000 waiting on condition [11fa31000]

java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <7f7a7e0e0> (a java.util.concurrent.Semaphore$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:969)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
at java.util.concurrent.Semaphore.acquire(Semaphore.java:286)
at brooklyn.event.basic.DependentConfiguration.waitInTaskForAttributeReady(DependentConfiguration.java:178)
at brooklyn.event.basic.DependentConfiguration$Builder$1.call(DependentConfiguration.java:441)
at brooklyn.util.task.BasicExecutionManager$3.call(BasicExecutionManager.java:352)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:695)

"brooklyn-execmanager-RkebfZSD-198" daemon prio=5 tid=7fe705cbf000 nid=0x11e531000 waiting on condition [11e530000]

java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <7f64b5dd0> (a java.util.concurrent.FutureTask$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:969)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281)
at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:218)
at java.util.concurrent.FutureTask.get(FutureTask.java:83)
at com.google.common.util.concurrent.ForwardingFuture.get(ForwardingFuture.java:63)
at brooklyn.util.task.BasicTask.get(BasicTask.java:304)
at brooklyn.event.basic.DependentConfiguration$3.call(DependentConfiguration.java:235)
at brooklyn.util.task.BasicExecutionManager$3.call(BasicExecutionManager.java:352)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:695)

The log (which I'll analyse in more depth tomorrow) includes:

2014-05-02 23:25:11,306 DEBUG i.b.c.b.s.d.BrooklynDslDeferredSupplier [brooklyn-execmanager-RkebfZSD-43]: Queuing task to resolve $brooklyn:formatString("jdbc:%s%s", component("db").attributeWhenReady("url.mapped"), "tradedb")
2014-05-02 23:25:11,307 DEBUG i.b.c.b.s.d.BrooklynDslDeferredSupplier [brooklyn-execmanager-RkebfZSD-43]: Queuing task to resolve $brooklyn:formatString("jdbc:%s%s", component("db").attributeWhenReady("url.mapped"), "tradedb")
2014-05-02 23:25:11,307 DEBUG i.b.c.b.s.d.BrooklynDslDeferredSupplier [brooklyn-execmanager-RkebfZSD-43]: Resolved MySqlNodeImpl{id=Co35ElLk} from $brooklyn:formatString("jdbc:%s%s", component("db").attributeWhenReady("url.mapped"), "tradedb")
2014-05-02 23:25:11,308 DEBUG b.m.i.LocalSubscriptionManager [brooklyn-execmanager-RkebfZSD-199]: Creating subscription iozhErDJ for WebsphereLibertyImpl{id=X4ulV4kP} on MySqlNodeImpl{id=Co35ElLk} Sensor: url.mapped (java.lang.Object) in SubscriptionContext(kxfnL)
...
2014-05-02 23:25:11,308 DEBUG b.m.i.LocalSubscriptionManager [brooklyn-execmanager-RkebfZSD-199]: Creating subscription iozhErDJ for WebsphereLibertyImpl{id=X4ulV4kP} on MySqlNodeImpl{id=Co35ElLk} Sensor: url.mapped (java.lang.Object) in SubscriptionContext(kxfnL)
2014-05-02 23:25:21,940 DEBUG i.c.n.subnet.SubnetEnrichers [brooklyn-execmanager-RkebfZSD-56]: sensor mapper transforming URI mysql://37.58.96.163:3306/ to mysql://37.58.96.163:49327/; target=37.58.96.163:49327
2014-05-02 23:25:21,941 DEBUG b.entity.basic.AbstractEntity [brooklyn-execmanager-RkebfZSD-56]: Emitting sensor notification entity.sensor.added value Sensor: url.mapped (java.lang.String) on MySqlNodeImpl{id=Co35ElLk}