NullPointerException when running `openhab:zigbee nodes` in console
piroma opened this issue · 2 comments
piroma commented
Outline
If I issue a openhab:zigbee nodes from the console, I receive an unexpected error during execution.
Tried with several firmwares on the coordinator (6.0.3, 6.7.0 or 6.9.1.0).
Tried with or without devices linked to coordinator (TRADFRI bulbs or Aqara TVOC Air Quality Monitor or TS0121 generic plug).
Exception at 17:59:02 below.
Configuration
| Configuration | Description |
|---|---|
| Coordinator used | POPP ZB-Stick (Zigbee) [rebranded Elecard ELR023] |
| openHAB version | 3.1.0 |
| Hardware | Raspberry Pi 3 Model B Rev 1.2 |
| Memory | 1GB |
| Java version | zulu11.48.21-ca-jdk11.0.11-linux_aarch32hf |
| Devices | Various or none |
Logs
openhab> openhab:zigbee ncpversion
Ember NCP version 6.9.1.0, EZSP version 8
openhab> openhab:zigbee nodes
An unexpected error occurred during execution.
openhab> log:display
17:58:56.595 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Command: 'log:clear' returned 'null'
17:58:56.843 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
17:58:56.845 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=2, ackNum=6, reTx=false, data=32 00 01 18 00]
17:58:56.853 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=3, reTx=false, data=32 80 01 18 00 02]
17:58:56.854 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=2, ackNum=6, reTx=false, data=32 00 01 18 00]
17:58:56.855 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame to receive queue. Queue length 0
17:58:56.856 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
17:58:56.857 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]
17:58:56.900 [DEBUG] [org.eclipse.jetty.io.IdleTimeout ] - SocketChannelEndPoint@c2ab86{l=/192.168.32.222:8080,r=/192.168.32.218:63388,OPEN,fill=-,flush=-,to=30000/30000}{io=0/0,kio=0,kro=1}->HttpConnection@1c71b49[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@3afd4e{s=COMMITTED}]=>HttpChannelOverHttp@bc4644{s=HttpChannelState@f42031{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=1,c=false/false,a=WAITING,uri=//openhabian:8080/rest/events/states,age=1651014} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
17:58:56.902 [DEBUG] [org.eclipse.jetty.io.IdleTimeout ] - SocketChannelEndPoint@c2ab86{l=/192.168.32.222:8080,r=/192.168.32.218:63388,OPEN,fill=-,flush=-,to=30002/30000}{io=0/0,kio=0,kro=1}->HttpConnection@1c71b49[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@3afd4e{s=COMMITTED}]=>HttpChannelOverHttp@bc4644{s=HttpChannelState@f42031{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=1,c=false/false,a=WAITING,uri=//openhabian:8080/rest/events/states,age=1651016} idle timeout expired
17:58:56.904 [DEBUG] [org.eclipse.jetty.io.FillInterest ] - onFail FillInterest@1dca750{null}
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[?:?]
at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[?:?]
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) [?:?]
17:58:56.908 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - ignored: WriteFlusher@d95f55{IDLE}->null
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[?:?]
at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[?:?]
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) [?:?]
17:58:56.913 [DEBUG] [org.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SocketChannelEndPoint@c2ab86{l=/192.168.32.222:8080,r=/192.168.32.218:63388,OPEN,fill=-,flush=-,to=30013/30000}{io=0/0,kio=0,kro=1}->HttpConnection@1c71b49[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@3afd4e{s=COMMITTED}]=>HttpChannelOverHttp@bc4644{s=HttpChannelState@f42031{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=1,c=false/false,a=WAITING,uri=//openhabian:8080/rest/events/states,age=1651027}
17:58:57.847 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
17:58:57.848 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=3, ackNum=7, reTx=false, data=33 00 01 18 00]
17:58:57.855 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=4, reTx=false, data=33 80 01 18 00 02]
17:58:57.857 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=3, ackNum=7, reTx=false, data=33 00 01 18 00]
17:58:57.858 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
17:58:57.858 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame to receive queue. Queue length 0
17:58:57.859 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]
17:58:58.850 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
17:58:58.851 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=4, ackNum=0, reTx=false, data=34 00 01 18 00]
17:58:58.858 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=5, reTx=false, data=34 80 01 18 00 02]
17:58:58.860 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=4, ackNum=0, reTx=false, data=34 00 01 18 00]
17:58:58.862 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
17:58:58.862 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame to receive queue. Queue length 0
17:58:58.863 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]
17:58:59.853 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
17:58:59.856 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=5, ackNum=1, reTx=false, data=35 00 01 18 00]
17:58:59.863 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=6, reTx=false, data=35 80 01 18 00 02]
17:58:59.864 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=5, ackNum=1, reTx=false, data=35 00 01 18 00]
17:58:59.866 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame to receive queue. Queue length 0
17:58:59.866 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
17:58:59.867 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]
17:59:00.857 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
17:59:00.859 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=6, ackNum=2, reTx=false, data=36 00 01 18 00]
17:59:00.866 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=7, reTx=false, data=36 80 01 18 00 02]
17:59:00.867 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=6, ackNum=2, reTx=false, data=36 00 01 18 00]
17:59:00.870 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame to receive queue. Queue length 0
17:59:00.870 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
17:59:00.871 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
17:59:01.861 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
17:59:01.862 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=7, ackNum=3, reTx=false, data=37 00 01 18 00]
17:59:01.870 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=0, reTx=false, data=37 80 01 18 00 02]
17:59:01.873 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=7, ackNum=3, reTx=false, data=37 00 01 18 00]
17:59:01.874 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame to receive queue. Queue length 0
17:59:01.874 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
17:59:01.876 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
17:59:02.048 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Executing command: 'openhab:zigbee nodes'
17:59:02.056 [ERROR] [ab.core.io.console.ConsoleInterpreter] - An error occurred while executing the console command.
java.lang.NullPointerException: null
at com.zsmartsystems.zigbee.ZigBeeDeviceType.getByValue(ZigBeeDeviceType.java:648) ~[?:?]
at com.zsmartsystems.zigbee.console.ZigBeeConsoleNodeListCommand.printNode(ZigBeeConsoleNodeListCommand.java:96) ~[?:?]
at com.zsmartsystems.zigbee.console.ZigBeeConsoleNodeListCommand.process(ZigBeeConsoleNodeListCommand.java:71) ~[?:?]
at org.openhab.binding.zigbee.console.internal.ZigBeeConsoleCommandExtension.handleZigbeeCommand(ZigBeeConsoleCommandExtension.java:149) ~[?:?]
at org.openhab.binding.zigbee.console.internal.ZigBeeConsoleCommandExtension.handleCommand(ZigBeeConsoleCommandExtension.java:117) ~[?:?]
at org.openhab.binding.zigbee.console.internal.ZigBeeConsoleCommandExtension.execute(ZigBeeConsoleCommandExtension.java:89) ~[?:?]
at org.openhab.core.io.console.ConsoleInterpreter.execute(ConsoleInterpreter.java:55) [bundleFile:?]
at org.openhab.core.io.console.karaf.internal.CommandWrapper.execute(CommandWrapper.java:78) [bundleFile:?]
at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:68) [bundleFile:4.3.2]
at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:86) [bundleFile:4.3.2]
at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:599) [bundleFile:4.3.2]
at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:526) [bundleFile:4.3.2]
at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:415) [bundleFile:4.3.2]
at org.apache.felix.gogo.runtime.Pipe.doCall(Pipe.java:416) [bundleFile:4.3.2]
at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:229) [bundleFile:4.3.2]
at org.apache.felix.gogo.runtime.Pipe.call(Pipe.java:59) [bundleFile:4.3.2]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
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) [?:?]
17:59:02.067 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Command: 'openhab:zigbee nodes' returned 'null'
17:59:02.864 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
17:59:02.866 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=0, ackNum=4, reTx=false, data=38 00 01 18 00]
17:59:02.873 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=1, reTx=false, data=38 80 01 18 00 02]
17:59:02.874 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=0, ackNum=4, reTx=false, data=38 00 01 18 00]
17:59:02.876 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame to receive queue. Queue length 0
17:59:02.876 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
17:59:02.877 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]
17:59:03.867 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
17:59:03.869 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=1, ackNum=5, reTx=false, data=39 00 01 18 00]
17:59:03.876 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=2, reTx=false, data=39 80 01 18 00 02]
17:59:03.877 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=1, ackNum=5, reTx=false, data=39 00 01 18 00]
17:59:03.879 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
17:59:03.879 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame to receive queue. Queue length 0
17:59:03.880 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]
17:59:04.871 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
17:59:04.873 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=2, ackNum=6, reTx=false, data=3A 00 01 18 00]
17:59:04.880 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=3, reTx=false, data=3A 80 01 18 00 02]
17:59:04.881 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=2, ackNum=6, reTx=false, data=3A 00 01 18 00]
17:59:04.882 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
17:59:04.883 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame to receive queue. Queue length 0
17:59:04.884 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]
17:59:05.807 [DEBUG] [org.eclipse.jetty.io.IdleTimeout ] - SocketChannelEndPoint@17086c9{l=/192.168.32.222:8080,r=/192.168.32.218:61271,OPEN,fill=-,flush=-,to=30000/30000}{io=0/0,kio=0,kro=1}->HttpConnection@13238a9[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@abd2d8{s=COMMITTED}]=>HttpChannelOverHttp@349942{s=HttpChannelState@11cfdbb{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=6,c=false/false,a=WAITING,uri=//openhabian:8080/rest/events/states,age=2027477} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
17:59:05.809 [DEBUG] [org.eclipse.jetty.io.IdleTimeout ] - SocketChannelEndPoint@17086c9{l=/192.168.32.222:8080,r=/192.168.32.218:61271,OPEN,fill=-,flush=-,to=30002/30000}{io=0/0,kio=0,kro=1}->HttpConnection@13238a9[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@abd2d8{s=COMMITTED}]=>HttpChannelOverHttp@349942{s=HttpChannelState@11cfdbb{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=6,c=false/false,a=WAITING,uri=//openhabian:8080/rest/events/states,age=2027480} idle timeout expired
17:59:05.811 [DEBUG] [org.eclipse.jetty.io.FillInterest ] - onFail FillInterest@d40753{null}
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[?:?]
at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[?:?]
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) [?:?]
17:59:05.816 [DEBUG] [org.eclipse.jetty.io.WriteFlusher ] - ignored: WriteFlusher@1785bbe{IDLE}->null
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[?:?]
at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[?:?]
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) [?:?]
17:59:05.822 [DEBUG] [org.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SocketChannelEndPoint@17086c9{l=/192.168.32.222:8080,r=/192.168.32.218:61271,OPEN,fill=-,flush=-,to=30015/30000}{io=0/0,kio=0,kro=1}->HttpConnection@13238a9[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@abd2d8{s=COMMITTED}]=>HttpChannelOverHttp@349942{s=HttpChannelState@11cfdbb{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=6,c=false/false,a=WAITING,uri=//openhabian:8080/rest/events/states,age=2027492}
17:59:05.875 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
17:59:05.876 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=3, ackNum=7, reTx=false, data=3B 00 01 18 00]
17:59:05.882 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=4, reTx=false, data=3B 80 01 18 00 02]
17:59:05.883 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=3, ackNum=7, reTx=false, data=3B 00 01 18 00]
17:59:05.884 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame to receive queue. Queue length 0
17:59:05.884 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
17:59:05.885 [DEBUG] [le.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]
17:59:06.333 [DEBUG] [le.osgi.LoggingCommandSessionListener] - Executing command: 'log:display'
17:59:06.337 [DEBUG] [org.apache.felix.configadmin ] - getConfiguration(pid=org.ops4j.pax.logging, location=null)
17:59:06.339 [DEBUG] [org.apache.felix.configadmin ] - Found cached configuration org.ops4j.pax.logging bound to ?
17:59:06.357 [DEBUG] [org.apache.felix.configadmin ] - getConfiguration(pid=org.ops4j.pax.logging, location=null)
17:59:06.358 [DEBUG] [org.apache.felix.configadmin ] - Found cached configuration org.ops4j.pax.logging bound to ?
17:59:06.380 [DEBUG] [org.apache.felix.configadmin ] - update(properties={felix.fileinstall.filename=file:/var/lib/openhab/etc/org.ops4j.pax.logging.cfg, org.ops4j.pax.logging.log4j2.config.file=/var/lib/openhab/etc/log4j2.xml, service.pid=org.ops4j.pax.logging})
17:59:06.381 [DEBUG] [org.apache.felix.configadmin ] - Updating config org.ops4j.pax.logging with {felix.fileinstall.filename=file:/var/lib/openhab/etc/org.ops4j.pax.logging.cfg, org.ops4j.pax.logging.log4j2.config.file=/var/lib/openhab/etc/log4j2.xml, service.pid=org.ops4j.pax.logging}
17:59:06.384 [DEBUG] [org.apache.felix.configadmin ] - Sending CM_UPDATED event for org.ops4j.pax.logging to [org.osgi.service.cm.SynchronousConfigurationListener, id=41, bundle=12/mvn:org.apache.felix/org.apache.felix.configadmin/1.9.22]
17:59:06.385 [DEBUG] [org.apache.felix.configadmin ] - Scheduling task Fire ConfigurationEvent: pid=org.ops4j.pax.logging
17:59:06.386 [DEBUG] [org.apache.felix.configadmin ] - Running task Fire ConfigurationEvent: pid=org.ops4j.pax.logging
17:59:06.387 [DEBUG] [org.apache.felix.configadmin ] - Sending CM_UPDATED event for org.ops4j.pax.logging to [org.osgi.service.cm.ConfigurationListener, id=115, bundle=12/mvn:org.apache.felix/org.apache.felix.configadmin/1.9.22]
17:59:06.387 [DEBUG] [org.apache.felix.configadmin ] - Scheduling task Update: pid=org.ops4j.pax.logging
17:59:06.388 [DEBUG] [org.apache.felix.configadmin ] - Running task Update: pid=org.ops4j.pax.logging
17:59:06.388 [DEBUG] [org.apache.felix.configadmin ] - UpdateConfiguration(org.ops4j.pax.logging) scheduled
17:59:06.388 [DEBUG] [ROOT ] - bundle org.apache.felix.scr:2.1.26 (72) configurationEvent: Handling UPDATED of Configuration PID=org.ops4j.pax.logging for component holders []
openhab>
cdjackson commented
I'd need to understand the devices etc in your network as the error is caused by something wrong elsewhere. Possibly there is a corrupt device - it's hard to say without seeing the devices in the XML files.
cdjackson commented
So from the XML files you've sent, the issue seems to be the following -:
<profileId>41440</profileId>
<deviceId>97</deviceId>
There is a bug in the definition of the ZGP profile ID that I will fix. I'll also prevent this throwing an exception if the device type is not known.
I'll close this as it is not an issue in the OH binding - it's in the underlying libraries.