changed notification of item state change listeners to asynchronous c…

[kaikreuzer]

…alls and made it robust in case exceptions are thrown by the listener

Signed-off-by: Kai Kreuzer kai@openhab.org

[maggu2810]

I received this error twice.

Running org.eclipse.smarthome.core.items.GroupItemTest
Tests run: 4, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 0.058 sec <<< FAILURE! - in org.eclipse.smarthome.core.items.GroupItemTest
assert that group item posts events for changes correctly(org.eclipse.smarthome.core.items.GroupItemTest)  Time elapsed: 0.026 sec  <<< FAILURE!
java.lang.AssertionError: 
Expected: is <1>
     but: was <0>
    at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
    at org.junit.Assert.assertThat(Assert.java:865)
    at org.junit.Assert.assertThat(Assert.java:832)
    at org.junit.Assert$assertThat.callStatic(Unknown Source)
    at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallStatic(CallSiteArray.java:53)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callStatic(AbstractCallSite.java:157)
    at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callStatic(AbstractCallSite.java:169)
    at org.eclipse.smarthome.core.items.GroupItemTest.assert that group item posts events for changes correctly(GroupItemTest.groovy:105)

testGetAllMembers(org.eclipse.smarthome.core.items.GroupItemTest)  Time elapsed: 0.013 sec
assert accepted command types cannot be changed(org.eclipse.smarthome.core.items.GroupItemTest)  Time elapsed: 0.008 sec
assert acceptedCommandTypes on GroupItems returns subset of command types supported by all members(org.eclipse.smarthome.core.items.GroupItemTest)  Time elapsed: 0.005 sec
Running org.eclipse.smarthome.core.items.GenericItemTest
Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.016 sec - in org.eclipse.smarthome.core.items.GenericItemTest
assert that item posts events for updates and changes correctly(org.eclipse.smarthome.core.items.GenericItemTest)  Time elapsed: 0.009 sec
assert that null as group name is not allowed for addGroupName(org.eclipse.smarthome.core.items.GenericItemTest)  Time elapsed: 0.001 sec
assert that null as group name is not allowed for removeGroupName(org.eclipse.smarthome.core.items.GenericItemTest)  Time elapsed: 0 sec
assert that null as group name is not allowed for addGroupNames(org.eclipse.smarthome.core.items.GenericItemTest)  Time elapsed: 0.001 sec
Running org.eclipse.smarthome.core.common.SafeMethodCallerTest
Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.731 sec - in org.eclipse.smarthome.core.common.SafeMethodCallerTest
call throws ExecutionException(org.eclipse.smarthome.core.common.SafeMethodCallerTest)  Time elapsed: 0.015 sec
call throws TimeoutException(org.eclipse.smarthome.core.common.SafeMethodCallerTest)  Time elapsed: 0.102 sec
call just logs TimeoutException(org.eclipse.smarthome.core.common.SafeMethodCallerTest)  Time elapsed: 0.102 sec
call executes method(org.eclipse.smarthome.core.common.SafeMethodCallerTest)  Time elapsed: 0.003 sec
call just logs ExecutionException(org.eclipse.smarthome.core.common.SafeMethodCallerTest)  Time elapsed: 0.002 sec
call does not throws TimeoutException if timeout is high enough(org.eclipse.smarthome.core.common.SafeMethodCallerTest)  Time elapsed: 0.501 sec
Running org.eclipse.smarthome.core.common.ThreadPoolManagerTest
Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.028 sec - in org.eclipse.smarthome.core.common.ThreadPoolManagerTest
get cached pool(org.eclipse.smarthome.core.common.ThreadPoolManagerTest)  Time elapsed: 0.013 sec
reconfiguring scheduled pool(org.eclipse.smarthome.core.common.ThreadPoolManagerTest)  Time elapsed: 0.004 sec
reconfiguring cached pool(org.eclipse.smarthome.core.common.ThreadPoolManagerTest)  Time elapsed: 0 sec
get configured scheduled pool(org.eclipse.smarthome.core.common.ThreadPoolManagerTest)  Time elapsed: 0 sec
get configured cached pool(org.eclipse.smarthome.core.common.ThreadPoolManagerTest)  Time elapsed: 0.001 sec
get scheduled pool(org.eclipse.smarthome.core.common.ThreadPoolManagerTest)  Time elapsed: 0 sec
Running org.eclipse.smarthome.core.events.AbstractEventFactoryTest
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.011 sec - in org.eclipse.smarthome.core.events.AbstractEventFactoryTest
AbstractEventFactory validates arguments(org.eclipse.smarthome.core.events.AbstractEventFactoryTest)  Time elapsed: 0.004 sec
AbstractEventFactory throws exception for not supported event types(org.eclipse.smarthome.core.events.AbstractEventFactoryTest)  Time elapsed: 0 sec
Running org.eclipse.smarthome.core.internal.events.OSGiEventManagerOSGiTest
Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.195 sec - in org.eclipse.smarthome.core.internal.events.OSGiEventManagerOSGiTest
OSGiEventManager validates events before posted(org.eclipse.smarthome.core.internal.events.OSGiEventManagerOSGiTest)  Time elapsed: 0.029 sec
OSGiEventManager dispatches diffent event types to corresponding subscribers correctly(org.eclipse.smarthome.core.internal.events.OSGiEventManagerOSGiTest)  Time elapsed: 0.124 sec
OSGiEventManager dispatches no event after subscriber unregistration(org.eclipse.smarthome.core.internal.events.OSGiEventManagerOSGiTest)  Time elapsed: 0.017 sec
OSGiEventManager dispatches no event after factory unregistration(org.eclipse.smarthome.core.internal.events.OSGiEventManagerOSGiTest)  Time elapsed: 0.01 sec
OSGiEventManager dispatches event data correctly(org.eclipse.smarthome.core.internal.events.OSGiEventManagerOSGiTest)  Time elapsed: 0.007 sec
Running org.eclipse.smarthome.core.internal.i18n.I18nProviderOSGiTest
Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.074 sec - in org.eclipse.smarthome.core.internal.i18n.I18nProviderOSGiTest
assert that getText via bundle is working properly(org.eclipse.smarthome.core.internal.i18n.I18nProviderOSGiTest)  Time elapsed: 0.042 sec
assert that getText with arguments delegates properly to getText without arguments(org.eclipse.smarthome.core.internal.i18n.I18nProviderOSGiTest)  Time elapsed: 0.003 sec
assert that getText without bundle is working properly(org.eclipse.smarthome.core.internal.i18n.I18nProviderOSGiTest)  Time elapsed: 0.002 sec
assert that getText with arguments via bundle is working properly(org.eclipse.smarthome.core.internal.i18n.I18nProviderOSGiTest)  Time elapsed: 0.019 sec
Running org.eclipse.smarthome.core.internal.items.ItemUpdaterOSGiTest
Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.195 sec - in org.eclipse.smarthome.core.internal.items.ItemUpdaterOSGiTest
assert ItemUpdater sets item state(org.eclipse.smarthome.core.internal.items.ItemUpdaterOSGiTest)  Time elapsed: 0.032 sec
assert ItemUpdater sends state changed event(org.eclipse.smarthome.core.internal.items.ItemUpdaterOSGiTest)  Time elapsed: 0.158 sec
Running org.eclipse.smarthome.core.internal.ItemTagTest
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.01 sec - in org.eclipse.smarthome.core.internal.ItemTagTest
assert tags are handled correctly(org.eclipse.smarthome.core.internal.ItemTagTest)  Time elapsed: 0.008 sec
Running org.eclipse.smarthome.core.internal.PortableBase64Test
testPerformanceJavaSE7 1528.346265 ms for 10000000 iterations on 1.8.0_92.
testPerformancePortableBase64 took 2463.740937 ms for 10000000 iterations on 1.8.0_92.
Tests run: 13, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 4.031 sec - in org.eclipse.smarthome.core.internal.PortableBase64Test
testDecodeInvalidPaddingMiddle(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 0.007 sec
testDecodeInvalidPaddingStart1(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 0 sec
testDecodeInvalidPaddingStart2(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 0 sec
testPerformanceJavaSE7(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 1.544 sec
testPerformanceJavaSE8(org.eclipse.smarthome.core.internal.PortableBase64Test) skipped
testGetStaticClasses(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 0.004 sec
testEncodeWhenClassNotInitialized(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 0.002 sec
testPerformancePortableBase64(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 2.464 sec
testDecodeInvalidCharacterDash(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 0 sec
testDecodeWhenClassNotInitialized(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 0 sec
testDecode(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 0.001 sec
testEncode(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 0 sec
testDecodeInvalidCharacterDot(org.eclipse.smarthome.core.internal.PortableBase64Test)  Time elapsed: 0 sec
Running org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest
Tests run: 13, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.215 sec - in org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest
assert ItemRegistryEventSubscribers receive events about item changes(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.071 sec
assert getItemsByTag returns no item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.01 sec
assert getItemsOfType returns item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.004 sec
assert getItems returns item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.004 sec
assert itemRegistryChangeListeners are informed about item changes(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.008 sec
assert getItemsByTag can filter by class and tag(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.004 sec
assert getItemsByTag returns item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.004 sec
assert itemRegistry sets and removes members of GroupItems(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.011 sec
assert getItemsByTagAndType returns item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.003 sec
assert itemRegistry is thread safe(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.068 sec
assert getItemsByTag with two tags returns item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.002 sec
assert itemRegistry keeps same instance on item updates without changes(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.013 sec
assert getItemsByTag can filter by class and tag with GenericItem(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.003 sec
Running org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest
Tests run: 8, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.075 sec - in org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest
assert two items with same name can not be added(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.011 sec
assert items are there once the factory gets added(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.025 sec
assert items are added as group members on deferred creation(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.01 sec
assert getItems returns item from registered ManagedItemProvider(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.006 sec
assert removal returns old value(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.004 sec
assert tags are stored and retrieve as well(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.004 sec
updating existing item returns old value(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.004 sec
assert remove recursively works(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.006 sec

Results :

Failed tests: 
  GroupItemTest.assert that group item posts events for changes correctly:105 
Expected: is <1>
     but: was <0>

Tests run: 159, Failures: 1, Errors: 0, Skipped: 1

I assume this could be related to this PR

[kaikreuzer]

I cannot reproduce this failure, the tests are always successful if I execute them locally.

Could you check whether #1712 makes a difference?

[maggu2810]

Thank you, seems to be solved.

[maggu2810]

And after another one, also another error

Tests run: 13, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.168 sec - in org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest
assert ItemRegistryEventSubscribers receive events about item changes(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.071 sec
assert getItemsByTag returns no item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.01 sec
assert getItemsOfType returns item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.003 sec
assert getItems returns item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.004 sec
assert itemRegistryChangeListeners are informed about item changes(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.009 sec
assert getItemsByTag can filter by class and tag(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.003 sec
assert getItemsByTag returns item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.003 sec
assert itemRegistry sets and removes members of GroupItems(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.01 sec
assert getItemsByTagAndType returns item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.003 sec
assert itemRegistry is thread safe(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.023 sec
assert getItemsByTag with two tags returns item from registered ItemProvider(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.004 sec
assert itemRegistry keeps same instance on item updates without changes(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.015 sec
assert getItemsByTag can filter by class and tag with GenericItem(org.eclipse.smarthome.core.internal.ItemRegistryOSGiTest)  Time elapsed: 0.003 sec
Running org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest
Tests run: 8, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.069 sec - in org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest
assert two items with same name can not be added(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.014 sec
assert items are there once the factory gets added(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.023 sec
assert items are added as group members on deferred creation(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.008 sec
assert getItems returns item from registered ManagedItemProvider(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.003 sec
assert removal returns old value(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.003 sec
assert tags are stored and retrieve as well(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.003 sec
updating existing item returns old value(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.004 sec
assert remove recursively works(org.eclipse.smarthome.core.storage.ManagedItemProviderOSGiTest)  Time elapsed: 0.005 sec

Results :

Failed tests: 
  GroupItemTest.assert that group item posts events for changes correctly:100->OSGiTest.waitForAssert:-1->OSGiTest.waitForAssert:181 
Expected: is <1>
     but: was <0>

Tests run: 159, Failures: 1, Errors: 0, Skipped: 1

[maggu2810]

Ah, its the same, just another line.
Don't know if the errors (e.g. #1713) are all related.
I also hit another one in "automation.module.timer.internal.RuntimeRuleTest".

[maggu2810]

After reverting the two commits (this change and the test fix), I was able to build ESH again.
So I assume we have some tests that cannot handle the async behavior correctly.
Perhaps my machine is faster or slower than others or my machine handles more threaded stuff parallel.

But with this PR, I am not able to build with enabled test execution.

[kaikreuzer]

Hm, pretty difficult for me to analyze as I do not get any local errors :-/
Any chance that you add some "waitForAsserts" around the failing asserts and see if this lets you build it again?

[maggu2810]

Hi Kai,
this makes the situation better (at least one time).

But before add a PR, one question.
Can't we change the default timeout for the waitFor[Assert] functions?

• waitFor
• waitForAssert

If we are using waitFor[Asssert] in a test, we normally want to that a condition met sometime and fail if not. I don't think we have tests that really tests that a condition is met in a given time period.

The normal use case should be that a test succeeds, if it takes some time, all is fine.
If the test fails, it should not matter if we have to wait one minute until it fails. Does it?

If a test would like to wait for not longer than e.g. 5 seconds, the timeout has to be set explicitly regardless of the default value.

So, WDYT about changing the default timeout from 1s to 1min?

[kaikreuzer]

Ok to change the timeout, but 1 min is a lot - I prefer a "fail fast". I would tend to say that whatever action takes more than 5-10 seconds should be considered to be a problem (and designing tests that REALLY expect to run longer than 10 seconds before an assertion is met is probably a bad style of writing tests as it will also slow down the successful builds).