Errors in logs - how to resolve?

Sundeep_Goel · January 3, 2022, 10:13am

Platform information:
- Hardware: rpi2
- openHAB version:3.2

Need help with following errors in openhab.log

Multiple Duplicate channels message e.g.

Scheduled runnable ended with an exception: java.lang.IllegalArgumentException: Duplicate channels mqtt: homeassistant_ecfabc9bf65a:6b640ad010:ecfabc9bf65a:ESPswitchfountain_5Fswitch#switch
Scheduled runnable ended with an exception: java.lang.IllegalArgumentException: Duplicate channels mqtt: homeassistant_30aea4131a48:6b640ad010:30aea4131a48:ESPswitchfront_5Fbalcony_5Ftube_5Flight#switch

[ssistant.internal.DiscoverComponents] - HomeAssistant discover error: thing xxxx commponent type is unsupported: number
[ERROR] [nternal.DiscoveryServiceRegistryImpl] - Cannot notify the DiscoveryListener ‘org.openhab.core.config.discovery.internal.PersistentInbox’ on Thing discovered event!
java.util.ConcurrentModificationException: null
[WARN ] [.transport.servlet.ServletController] - Can’t find the request for http://192.168.1.71:8080/rest/items/xxxx/state’s Observer

rlkoshak · January 3, 2022, 4:54pm

These all appear to come from MQTT, in particular home assistant discovered Things. Have these errors started since upgrading to 3.2? Have you tried deleting the Things and letting them be rediscovered? Is this a new device added to your system?

Sundeep_Goel · January 3, 2022, 6:29pm

No, haven’t tried deleting and rediscovery yet. Was concerned with having to spend a lot of time configuring.

I’ll extract definitions into a file from the cli, and then give it a shot.

Can you advise how mqtt binding / broker creates names? I want to shorten current ones since they are too long.

rlkoshak · January 3, 2022, 6:48pm

They are automatically discovered and created Things? If you ensure they get added with the same IDs as the old Things there is nothing to configure.

If they are added with a different ID, you’ll have to recreate the links to the Items.

When you click on the Thing in the Inbox there is an “Add as Thing (with custom ID)” option.

Sundeep_Goel · January 4, 2022, 5:34am

Did a foolish mistake, vs deleting for only MQTT Things ran command “things clear” from CLI. obviously all configurations got deleted. Scratching my head on how to recover (i mean the connection / configuration details sitting underneath) for following:

mail:smtp:Smtp** (Type=Thing, Status=ONLINE, Label=SMTP Server, Bridge=null)
telegram:telegramBot:Telegram_Bot_sherlock (Type=Thing, Status=ONLINE, Label=Telegram Bot, Bridge=null)
astro:moon:local** (Type=Thing, Status=ONLINE, Label=Local Moon, Bridge=null)
astro:sun:local** (Type=Thing, Status=ONLINE, Label=Local Sun, Bridge=null)
telegram:telegramBot:Telegram_Bot_watson (Type=Thing, Status=ONLINE, Label=Telegram Bot, Bridge=null)
airquality:aqi:local** (Type=Thing, Status=UNINITIALIZED, Label=Local Air Quality, Bridge=null)
openweathermap:onecall:1c027ae5a5:local (Type=Thing, Status=UNINITIALIZED (DISABLED), Label=One Call API Weather and Forecast, Bridge=openweathermap:weather-api:1c027ae5a5)
openweathermap:weather-and-forecast:1c027ae5a5:local (Type=Thing, Status=ONLINE, Label=Local weather and forecast, Bridge=openweathermap:weather-api:1c027ae5a5)
openweathermap:air-pollution:1c027ae5a5:local (Type=Thing, Status=ONLINE, Label=Local Air Pollution, Bridge=openweathermap:weather-api:1c027ae5a5)
openweathermap:weather-api:1c027ae5a5 (Type=Bridge, Status=ONLINE, Label=OpenWeatherMap Account, Bridge=null)
openweathermap:onecall-history:1c027ae5a5:local (Type=Thing, Status=UNINITIALIZED (DISABLED), Label=One Call API History Data, Bridge=openweathermap:weather-api:1c027ae5a5)

Sundeep_Goel · January 4, 2022, 6:20am

Also getting following type of errors for all Things rediscovered via MQTT Broker - like

Could not create channel ‘xxx’, because channel type ‘mqtt:yyyy’ could not be found**.
*Could not create channels for channel group ‘zzz’ for thing type

Please advise required step to resolve.

2022-01-04 11:38:13.399 [WARN ] [re.thing.internal.ThingFactoryHelper] - **Could not create channel** 'ESPswitchdining3#switch', **because channel type 'mqtt:ESPswitchdining3_switch' could not be found**.
2022-01-04 11:38:13.403 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channel 'ESPswitchdining_5F3#switch', because channel type 'mqtt:ESPswitchdining_5F3_switch' could not be found.
2022-01-04 11:38:13.407 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channel 'ESPswitchdining_5F2#switch', because channel type 'mqtt:ESPswitchdining_5F2_switch' could not be found.
2022-01-04 11:38:13.411 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channel 'ESPswitchdining_5F1#switch', because channel type 'mqtt:ESPswitchdining_5F1_switch' could not be found.
2022-01-04 11:38:13.415 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channel 'mqtt:homeassistant_840d8e494ce9:myMQTTBroker:840d8e494ce9', because channel group type 'mqtt:ESPswitchdining3' could not be found.
2022-01-04 11:38:13.451 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channels for channel group 'ESPswitchdining_5F3' for thing type 'mqtt:homeassistant_840d8e494ce9:myMQTTBroker:840d8e494ce9', because channel group type 'mqtt:ESPswitchdining_5F3' could not be found.
2022-01-04 11:38:13.454 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channels for channel group 'ESPswitchdining_5F2' for thing type 'mqtt:homeassistant_840d8e494ce9:myMQTTBroker:840d8e494ce9', because channel group type 'mqtt:ESPswitchdining_5F2' could not be found.
2022-01-04 11:38:13.457 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channels for channel group 'ESPswitchdining_5F1' for thing type 'mqtt:homeassistant_840d8e494ce9:myMQTTBroker:840d8e494ce9', because channel group type 'mqtt:ESPswitchdining_5F1' could not be found.
2022-01-04 11:38:13.459 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channels for channel group 'ESPswitchdining1' for thing type 'mqtt:homeassistant_840d8e494ce9:myMQTTBroker:840d8e494ce9', because channel group type 'mqtt:ESPswitchdining1' could not be found.

rlkoshak · January 4, 2022, 2:06pm

In $OH-USERDATA/jsondb/backup there are automatic backups of the things and other configs.

The errors are probably because while you deleted all the Things, the Links to the Items still exist. You need to restore your Things from the backup or delete all the links that point to Things that no longer exist.

Sascha_Billian · January 4, 2022, 2:36pm

@Sundeep_Goel Please use Code fences, it makes it way better to read:

Result:

2022-01-04 11:38:13.399 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channel ‘ESPswitchdining3#switch’, because channel type ‘mqtt:ESPswitchdining3_switch’ could not be found.
2022-01-04 11:38:13.403 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channel ‘ESPswitchdining_5F3#switch’, because channel type ‘mqtt:ESPswitchdining_5F3_switch’ could not be found.
2022-01-04 11:38:13.407 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channel ‘ESPswitchdining_5F2#switch’, because channel type ‘mqtt:ESPswitchdining_5F2_switch’ could not be found.
2022-01-04 11:38:13.411 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channel ‘ESPswitchdining_5F1#switch’, because channel type ‘mqtt:ESPswitchdining_5F1_switch’ could not be found.
2022-01-04 11:38:13.415 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channel ‘mqtt:homeassistant_840d8e494ce9:myMQTTBroker:840d8e494ce9’, because channel group type ‘mqtt:ESPswitchdining3’ could not be found.
2022-01-04 11:38:13.451 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channels for channel group ‘ESPswitchdining_5F3’ for thing type ‘mqtt:homeassistant_840d8e494ce9:myMQTTBroker:840d8e494ce9’, because channel group type ‘mqtt:ESPswitchdining_5F3’ could not be found.
2022-01-04 11:38:13.454 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channels for channel group ‘ESPswitchdining_5F2’ for thing type ‘mqtt:homeassistant_840d8e494ce9:myMQTTBroker:840d8e494ce9’, because channel group type ‘mqtt:ESPswitchdining_5F2’ could not be found.
2022-01-04 11:38:13.457 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channels for channel group ‘ESPswitchdining_5F1’ for thing type ‘mqtt:homeassistant_840d8e494ce9:myMQTTBroker:840d8e494ce9’, because channel group type ‘mqtt:ESPswitchdining_5F1’ could not be found.
2022-01-04 11:38:13.459 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channels for channel group ‘ESPswitchdining1’ for thing type ‘mqtt:homeassistant_840d8e494ce9:myMQTTBroker:840d8e494ce9’, because channel group type ‘mqtt:ESPswitchdining1’ could not be found.

Sundeep_Goel · January 5, 2022, 12:52pm

Deleted things & links, and set them up again. Also, did a cache purge from cli. Steps reduced number of duplicates but did not eliminate. Finally purged mosquitto mqtt db, that seems to have the desired effect, no duplicates (yet).

Have also increased log level on mqtt bindings to DEBUG to get more data in case issue re-surfaces.

Sundeep_Goel · January 8, 2022, 1:57pm

And the duplicates are back , not as many as before , but still back


2022-01-08 18:23:43.440 [INFO ] [org.openhab.core.model.script.Power ] - Mains FailedOFF , OFF
2022-01-08 18:23:44.218 [INFO ] [rg.openhab.core.model.script.Battery] - Battery Flag status 20% OFF , OFF
2022-01-08 18:23:44.243 [WARN ] [gram.internal.action.TelegramActions] - Exception occured whilst sending message:java.io.InterruptedIOException: interrupted
2022-01-08 18:23:50.459 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.IllegalArgumentException: Duplicate channels mqtt:homeassistant_ecfabc9bead9:myMQTTBroker:ecfabc9bead9:ESPswitchdining_5Fplant_5Fstair_5Flight_5Fpir#switch
	at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:152) ~[?:?]
	at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:144) ~[?:?]
	at org.openhab.core.thing.util.ThingHelper.addChannelsToThing(ThingHelper.java:105) ~[?:?]
	at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:292) ~[?:?]
	at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:1) ~[?:?]
	at org.openhab.binding.mqtt.generic.tools.DelayedBatchProcessing.run(DelayedBatchProcessing.java:110) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]
2022-01-08 18:23:53.008 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.IllegalArgumentException: Duplicate channels mqtt:homeassistant_5ccf7f0dfaa0:myMQTTBroker:5ccf7f0dfaa0:ESPsensorbatterycharge#sensor
	at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:152) ~[?:?]
	at org.openhab.core.thing.util.ThingHelper.ensureUniqueChannels(ThingHelper.java:144) ~[?:?]
	at org.openhab.core.thing.util.ThingHelper.addChannelsToThing(ThingHelper.java:105) ~[?:?]
	at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:292) ~[?:?]
	at org.openhab.binding.mqtt.homeassistant.internal.handler.HomeAssistantThingHandler.accept(HomeAssistantThingHandler.java:1) ~[?:?]
	at org.openhab.binding.mqtt.generic.tools.DelayedBatchProcessing.run(DelayedBatchProcessing.java:110) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]

How do I debug this further ? in particular which log level can i increase to get information on which mqtt message is triggering this behaviour. Once that is known i maybe able to trace the root casue.

rlkoshak · January 8, 2022, 2:51pm

Well, it’s telling you what Channel is the problem. mqtt:homeassistant_5ccf7f0dfaa0:myMQTTBroker:5ccf7f0dfaa0:ESPsensorbatterycharge#sensor

What topic does that curdling to?

Sundeep_Goel · January 8, 2022, 3:33pm

the item definition is :-

Number Inverter_BatteryCharge "BatteryCharge" (gESP8266_inverter) ["Measurement", "Current"] { channel="mqtt:homeassistant_5ccf7f0dfaa0:myMQTTBroker:5ccf7f0dfaa0:ESPsensorbatterycharge#sensor" }

The topic are not explicitly defined but picked up via the mqtt (homeassistant) binding. is there a way to list them via the console ?

Also executed links list from the cli, there is only one entry with the above name

Inverter_BatteryCharge -> mqtt:homeassistant_5ccf7f0dfaa0:myMQTTBroker:5ccf7f0dfaa0:ESPsensorbatterycharge#sensor Configuration[]

rlkoshak · January 8, 2022, 4:38pm

I don’t care about the item. The error is occurring before we get to that point.

What is the Thing? Hook an MQTT clients up to your broker and look around at the topics there. It should be relatively obvious which topics correspond to that Thing and which topics correspond to that channel. MQTT Explorer is a good choice.