search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.86k stars 3.57k forks source link

[avmfritz] 2 FRITZ!DECT 200 NullPointerException because PowerMeterModel missing #1885

Closed NorbertHD closed 7 years ago

NorbertHD commented 7 years ago

Sometimes when I start openHAB on Windows 10 my 2 FRITZ!DECT 200 are correctly read. See log:

2017-02-11 16:25:18.008 [INFO ] [ore.internal.i18n.LocaleProviderImpl] - Locale set to de_DE
2017-02-11 16:25:20.655 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2017-02-11 16:25:20.820 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-02-11 16:25:20.846 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-02-11 16:25:20.880 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-02-11 16:25:20.892 [DEBUG] [org.openhab.binding.avmfritz        ] - BundleEvent STARTING - org.openhab.binding.avmfritz
2017-02-11 16:25:20.893 [DEBUG] [org.openhab.binding.avmfritz        ] - BundleEvent STARTED - org.openhab.binding.avmfritz
2017-02-11 16:25:20.898 [DEBUG] [org.openhab.binding.avmfritz        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={component.name=org.openhab.binding.avmfritz.discovery.bridge, component.id=153, service.id=286, service.bundleid=183, service.scope=bundle} - org.openhab.binding.avmfritz
2017-02-11 16:25:20.947 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 16:25:20.951 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 16:25:20.951 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 16:25:20.952 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 16:25:20.954 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 16:25:20.954 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 16:25:20.973 [DEBUG] [ternal.discovery.AvmDiscoveryService] - initialize discovery service
2017-02-11 16:25:20.973 [DEBUG] [ternal.discovery.AvmDiscoveryService] - start background scanning job
2017-02-11 16:25:20.976 [DEBUG] [org.openhab.binding.avmfritz        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=289, service.bundleid=183, service.scope=singleton} - org.openhab.binding.avmfritz
2017-02-11 16:25:20.989 [DEBUG] [org.openhab.binding.avmfritz        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.avmfritz.internal.HandlerFactory, component.id=154, service.id=288, service.bundleid=183, service.scope=bundle} - org.openhab.binding.avmfritz
2017-02-11 16:25:21.010 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - About to initialize bridge fritzbox
2017-02-11 16:25:21.016 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 16:25:21.016 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 16:25:21.020 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 16:25:21.021 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 16:25:21.028 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - discovered fritzaha bridge initialized: org.openhab.binding.avmfritz.config.AvmFritzConfiguration@160da14e[IP=192.168.178.1,port=<null>,proto=http,user=<null>,password=********,pollingInterval=15,asyncTimeout=10000,syncTimeout=2000]
2017-02-11 16:25:21.555 [DEBUG] [ternal.hardware.FritzahaWebInterface] - Starting with SID 53d9fafd676bf5e4
2017-02-11 16:25:21.556 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - start polling job at intervall 15
2017-02-11 16:25:22.557 [DEBUG] [g.avmfritz.handler.DeviceListPolling] - polling fritzbox org.openhab.binding.avmfritz.config.AvmFritzConfiguration@160da14e[IP=192.168.178.1,port=<null>,proto=http,user=<null>,password=********,pollingInterval=15,asyncTimeout=10000,syncTimeout=2000]
2017-02-11 16:25:22.559 [DEBUG] [ternal.hardware.FritzahaWebInterface] - GETting URL http://192.168.178.1/webservices/homeautoswitch.lua?switchcmd=getdevicelistinfos&sid=53d9fafd676bf5e4
2017-02-11 16:25:22.867 [DEBUG] [nal.hardware.FritzahaContentExchange] - HTTP response 200
2017-02-11 16:25:22.867 [DEBUG] [nal.hardware.FritzahaContentExchange] - HTTP response 200
2017-02-11 16:25:22.868 [DEBUG] [nal.hardware.FritzahaContentExchange] - response complete: <devicelist version="1"><device identifier="08761 0005102" id="16" functionbitmask="896" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Kühlschrank</name><switch><state>1</state><mode>manuell</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>350</power><energy>1132377</energy></powermeter><temperature><celsius>210</celsius><offset>0</offset></temperature></device><device identifier="08761 0039731" id="17" functionbitmask="2944" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Klimaanlage</name><switch><state>0</state><mode>auto</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>0</power><energy>625024</energy></powermeter><temperature><celsius>150</celsius><offset>0</offset></temperature></device></devicelist>

2017-02-11 16:25:22.902 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - set device model: org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@43bd0b4e[ain=087610005102,bitmask=896,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=16,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Kühlschrank,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@5a078f45[state=1,mode=manuell,lock=0],org.openhab.binding.avmfritz.internal.ahamodel.PowerMeterModel@7ac313e6[power=0.350,energy=1132.377],org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@40e68b29[celsius=21.0,offset=0.0]]
2017-02-11 16:25:22.903 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - update thing avmfritz:FRITZ_DECT_200:192_168_178_1:087610005102 with device model: org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@43bd0b4e[ain=087610005102,bitmask=896,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=16,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Kühlschrank,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@5a078f45[state=1,mode=manuell,lock=0],org.openhab.binding.avmfritz.internal.ahamodel.PowerMeterModel@7ac313e6[power=0.350,energy=1132.377],org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@40e68b29[celsius=21.0,offset=0.0]]
2017-02-11 16:25:22.904 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - about to update avmfritz:FRITZ_DECT_200:192_168_178_1:087610005102 from org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@43bd0b4e[ain=087610005102,bitmask=896,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=16,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Kühlschrank,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@5a078f45[state=1,mode=manuell,lock=0],org.openhab.binding.avmfritz.internal.ahamodel.PowerMeterModel@7ac313e6[power=0.350,energy=1132.377],org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@40e68b29[celsius=21.0,offset=0.0]]
2017-02-11 16:25:22.908 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - set device model: org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@1b44c7ef[ain=087610039731,bitmask=2944,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=17,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Klimaanlage,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@20ad9998[state=0,mode=auto,lock=0],org.openhab.binding.avmfritz.internal.ahamodel.PowerMeterModel@23db087a[power=0.000,energy=625.024],org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@31f1a2f3[celsius=15.0,offset=0.0]]
2017-02-11 16:25:22.908 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - update thing avmfritz:FRITZ_DECT_200:192_168_178_1:087610039731 with device model: org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@1b44c7ef[ain=087610039731,bitmask=2944,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=17,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Klimaanlage,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@20ad9998[state=0,mode=auto,lock=0],org.openhab.binding.avmfritz.internal.ahamodel.PowerMeterModel@23db087a[power=0.000,energy=625.024],org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@31f1a2f3[celsius=15.0,offset=0.0]]
2017-02-11 16:25:22.909 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - about to update avmfritz:FRITZ_DECT_200:192_168_178_1:087610039731 from org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@1b44c7ef[ain=087610039731,bitmask=2944,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=17,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Klimaanlage,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@20ad9998[state=0,mode=auto,lock=0],org.openhab.binding.avmfritz.internal.ahamodel.PowerMeterModel@23db087a[power=0.000,energy=625.024],org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@31f1a2f3[celsius=15.0,offset=0.0]]
2017-02-11 16:25:25.974 [DEBUG] [ternal.discovery.AvmDiscoveryService] - starting scan on bridge avmfritz:fritzbox:192_168_178_1
2017-02-11 16:25:25.977 [DEBUG] [ternal.hardware.FritzahaWebInterface] - GETting URL http://192.168.178.1/webservices/homeautoswitch.lua?switchcmd=getdevicelistinfos&sid=53d9fafd676bf5e4
2017-02-11 16:25:26.285 [DEBUG] [nal.hardware.FritzahaContentExchange] - HTTP response 200
2017-02-11 16:25:26.285 [DEBUG] [nal.hardware.FritzahaContentExchange] - HTTP response 200
2017-02-11 16:25:26.286 [DEBUG] [nal.hardware.FritzahaContentExchange] - response complete: <devicelist version="1"><device identifier="08761 0005102" id="16" functionbitmask="896" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Kühlschrank</name><switch><state>1</state><mode>manuell</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>350</power><energy>1132377</energy></powermeter><temperature><celsius>210</celsius><offset>0</offset></temperature></device><device identifier="08761 0039731" id="17" functionbitmask="2944" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Klimaanlage</name><switch><state>0</state><mode>auto</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>0</power><energy>625024</energy></powermeter><temperature><celsius>150</celsius><offset>0</offset></temperature></device></devicelist>

2017-02-11 16:25:26.286 [DEBUG] [.callbacks.FritzAhaDiscoveryCallback] - discovery callback response <devicelist version="1"><device identifier="08761 0005102" id="16" functionbitmask="896" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Kühlschrank</name><switch><state>1</state><mode>manuell</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>350</power><energy>1132377</energy></powermeter><temperature><celsius>210</celsius><offset>0</offset></temperature></device><device identifier="08761 0039731" id="17" functionbitmask="2944" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Klimaanlage</name><switch><state>0</state><mode>auto</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>0</power><energy>625024</energy></powermeter><temperature><celsius>150</celsius><offset>0</offset></temperature></device></devicelist>

Some other time at start there are NullPointerExceptions because PowerMeterModel object is missing . This doesn't change until I restart openHAB. See log:

2017-02-11 15:53:15.844 [INFO ] [ore.internal.i18n.LocaleProviderImpl] - Locale set to de_DE
2017-02-11 15:53:18.443 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2017-02-11 15:53:18.626 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-02-11 15:53:18.650 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-02-11 15:53:18.672 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-02-11 15:53:18.684 [DEBUG] [org.openhab.binding.avmfritz        ] - BundleEvent STARTING - org.openhab.binding.avmfritz
2017-02-11 15:53:18.685 [DEBUG] [org.openhab.binding.avmfritz        ] - BundleEvent STARTED - org.openhab.binding.avmfritz
2017-02-11 15:53:18.708 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 15:53:18.710 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 15:53:18.711 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 15:53:18.712 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 15:53:18.712 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 15:53:18.712 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 15:53:18.713 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 15:53:18.713 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 15:53:18.714 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 15:53:18.714 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 15:53:18.714 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 15:53:18.715 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 15:53:18.717 [DEBUG] [org.openhab.binding.avmfritz        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.UpnpDiscoveryParticipant}={component.name=org.openhab.binding.avmfritz.discovery.bridge, component.id=153, service.id=286, service.bundleid=183, service.scope=bundle} - org.openhab.binding.avmfritz
2017-02-11 15:53:18.759 [DEBUG] [org.openhab.binding.avmfritz        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.avmfritz.internal.HandlerFactory, component.id=154, service.id=288, service.bundleid=183, service.scope=bundle} - org.openhab.binding.avmfritz
2017-02-11 15:53:18.776 [DEBUG] [ternal.discovery.AvmDiscoveryService] - initialize discovery service
2017-02-11 15:53:18.776 [DEBUG] [ternal.discovery.AvmDiscoveryService] - start background scanning job
2017-02-11 15:53:18.777 [DEBUG] [org.openhab.binding.avmfritz        ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=289, service.bundleid=183, service.scope=singleton} - org.openhab.binding.avmfritz
2017-02-11 15:53:18.778 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 15:53:18.778 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 15:53:18.781 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered on /192.168.178.40
2017-02-11 15:53:18.782 [DEBUG] [iscovery.AvmUpnpDiscoveryParticipant] - discovered: AVM Berlin FRITZ!Box 7490 (UI) 1und1 at 192.168.178.1
2017-02-11 15:53:18.795 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - About to initialize bridge fritzbox
2017-02-11 15:53:18.811 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - discovered fritzaha bridge initialized: org.openhab.binding.avmfritz.config.AvmFritzConfiguration@71465e99[IP=192.168.178.1,port=<null>,proto=http,user=<null>,password=********,pollingInterval=15,asyncTimeout=10000,syncTimeout=2000]
2017-02-11 15:53:19.286 [DEBUG] [ternal.hardware.FritzahaWebInterface] - Starting with SID 59731859be37af90
2017-02-11 15:53:19.286 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - start polling job at intervall 15
2017-02-11 15:53:20.288 [DEBUG] [g.avmfritz.handler.DeviceListPolling] - polling fritzbox org.openhab.binding.avmfritz.config.AvmFritzConfiguration@71465e99[IP=192.168.178.1,port=<null>,proto=http,user=<null>,password=********,pollingInterval=15,asyncTimeout=10000,syncTimeout=2000]
2017-02-11 15:53:20.290 [DEBUG] [ternal.hardware.FritzahaWebInterface] - GETting URL http://192.168.178.1/webservices/homeautoswitch.lua?switchcmd=getdevicelistinfos&sid=59731859be37af90
2017-02-11 15:53:20.605 [DEBUG] [nal.hardware.FritzahaContentExchange] - HTTP response 200
2017-02-11 15:53:20.605 [DEBUG] [nal.hardware.FritzahaContentExchange] - HTTP response 200
2017-02-11 15:53:20.606 [DEBUG] [nal.hardware.FritzahaContentExchange] - response complete: <devicelist version="1"><device identifier="08761 0005102" id="16" functionbitmask="896" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Kühlschrank</name><switch><state>1</state><mode>manuell</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>350</power><energy>1132361</energy></powermeter><temperature><celsius>210</celsius><offset>0</offset></temperature></device><device identifier="08761 0039731" id="17" functionbitmask="2944" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Klimaanlage</name><switch><state>0</state><mode>auto</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>0</power><energy>625024</energy></powermeter><temperature><celsius>135</celsius><offset>0</offset></temperature></device></devicelist>

2017-02-11 15:53:20.634 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - set device model: org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@5ae11065[ain=087610005102,bitmask=896,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=16,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Kühlschrank,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@499b66b0[state=1,mode=manuell,lock=0],<null>,org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@564bc83[celsius=21.0,offset=0.0]]
2017-02-11 15:53:20.634 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - update thing avmfritz:FRITZ_DECT_200:192_168_178_1:087610005102 with device model: org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@5ae11065[ain=087610005102,bitmask=896,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=16,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Kühlschrank,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@499b66b0[state=1,mode=manuell,lock=0],<null>,org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@564bc83[celsius=21.0,offset=0.0]]
2017-02-11 15:53:20.635 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - about to update avmfritz:FRITZ_DECT_200:192_168_178_1:087610005102 from org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@5ae11065[ain=087610005102,bitmask=896,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=16,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Kühlschrank,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@499b66b0[state=1,mode=manuell,lock=0],<null>,org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@564bc83[celsius=21.0,offset=0.0]]
2017-02-11 15:53:20.637 [ERROR] [.binding.avmfritz.handler.BoxHandler] -
java.lang.NullPointerException
    at org.openhab.binding.avmfritz.handler.BoxHandler.updateThingFromDevice(BoxHandler.java:165)[183:org.openhab.binding.avmfritz:2.1.0.201702102300]
    at org.openhab.binding.avmfritz.handler.BoxHandler.addDeviceList(BoxHandler.java:129)[183:org.openhab.binding.avmfritz:2.1.0.201702102300]
    at org.openhab.binding.avmfritz.internal.hardware.callbacks.FritzAhaUpdateXmlCallback.execute(FritzAhaUpdateXmlCallback.java:70)[183:org.openhab.binding.avmfritz:2.1.0.201702102300]
    at org.openhab.binding.avmfritz.internal.hardware.FritzahaContentExchange.onComplete(FritzahaContentExchange.java:71)[183:org.openhab.binding.avmfritz:2.1.0.201702102300]
    at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:193)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:185)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:453)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:400)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:266)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.http.HttpParser.parseContent(HttpParser.java:1487)[71:org.eclipse.jetty.http:9.2.19.v20160908]
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1245)[71:org.eclipse.jetty.http:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:156)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:117)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:69)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:89)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:123)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)[72:org.eclipse.jetty.io:9.2.19.v20160908]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)[83:org.eclipse.jetty.util:9.2.19.v20160908]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)[83:org.eclipse.jetty.util:9.2.19.v20160908]
    at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-02-11 15:53:20.639 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - set device model: org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@758b1210[ain=087610039731,bitmask=2944,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=17,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Klimaanlage,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@7f84902d[state=0,mode=auto,lock=0],<null>,org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@478bac91[celsius=13.5,offset=0.0]]
2017-02-11 15:53:20.639 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - update thing avmfritz:FRITZ_DECT_200:192_168_178_1:087610039731 with device model: org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@758b1210[ain=087610039731,bitmask=2944,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=17,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Klimaanlage,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@7f84902d[state=0,mode=auto,lock=0],<null>,org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@478bac91[celsius=13.5,offset=0.0]]
2017-02-11 15:53:20.639 [DEBUG] [.binding.avmfritz.handler.BoxHandler] - about to update avmfritz:FRITZ_DECT_200:192_168_178_1:087610039731 from org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@758b1210[ain=087610039731,bitmask=2944,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=17,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Klimaanlage,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@7f84902d[state=0,mode=auto,lock=0],<null>,org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@478bac91[celsius=13.5,offset=0.0]]
2017-02-11 15:53:20.640 [ERROR] [.binding.avmfritz.handler.BoxHandler] -
java.lang.NullPointerException
    at org.openhab.binding.avmfritz.handler.BoxHandler.updateThingFromDevice(BoxHandler.java:165)[183:org.openhab.binding.avmfritz:2.1.0.201702102300]
    at org.openhab.binding.avmfritz.handler.BoxHandler.addDeviceList(BoxHandler.java:129)[183:org.openhab.binding.avmfritz:2.1.0.201702102300]
    at org.openhab.binding.avmfritz.internal.hardware.callbacks.FritzAhaUpdateXmlCallback.execute(FritzAhaUpdateXmlCallback.java:70)[183:org.openhab.binding.avmfritz:2.1.0.201702102300]
    at org.openhab.binding.avmfritz.internal.hardware.FritzahaContentExchange.onComplete(FritzahaContentExchange.java:71)[183:org.openhab.binding.avmfritz:2.1.0.201702102300]
    at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:193)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:185)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:453)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.HttpReceiver.responseSuccess(HttpReceiver.java:400)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:266)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.http.HttpParser.parseContent(HttpParser.java:1487)[71:org.eclipse.jetty.http:9.2.19.v20160908]
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1245)[71:org.eclipse.jetty.http:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:156)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:117)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:69)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:89)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:123)[69:org.eclipse.jetty.client:9.2.19.v20160908]
    at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)[72:org.eclipse.jetty.io:9.2.19.v20160908]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)[83:org.eclipse.jetty.util:9.2.19.v20160908]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)[83:org.eclipse.jetty.util:9.2.19.v20160908]
    at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-02-11 15:53:23.778 [DEBUG] [ternal.discovery.AvmDiscoveryService] - starting scan on bridge avmfritz:fritzbox:192_168_178_1
2017-02-11 15:53:23.780 [DEBUG] [ternal.hardware.FritzahaWebInterface] - GETting URL http://192.168.178.1/webservices/homeautoswitch.lua?switchcmd=getdevicelistinfos&sid=59731859be37af90
2017-02-11 15:53:24.089 [DEBUG] [nal.hardware.FritzahaContentExchange] - HTTP response 200
2017-02-11 15:53:24.089 [DEBUG] [nal.hardware.FritzahaContentExchange] - HTTP response 200
2017-02-11 15:53:24.090 [DEBUG] [nal.hardware.FritzahaContentExchange] - response complete: <devicelist version="1"><device identifier="08761 0005102" id="16" functionbitmask="896" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Kühlschrank</name><switch><state>1</state><mode>manuell</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>350</power><energy>1132361</energy></powermeter><temperature><celsius>210</celsius><offset>0</offset></temperature></device><device identifier="08761 0039731" id="17" functionbitmask="2944" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Klimaanlage</name><switch><state>0</state><mode>auto</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>0</power><energy>625024</energy></powermeter><temperature><celsius>135</celsius><offset>0</offset></temperature></device></devicelist>

2017-02-11 15:53:24.090 [DEBUG] [.callbacks.FritzAhaDiscoveryCallback] - discovery callback response <devicelist version="1"><device identifier="08761 0005102" id="16" functionbitmask="896" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Kühlschrank</name><switch><state>1</state><mode>manuell</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>350</power><energy>1132361</energy></powermeter><temperature><celsius>210</celsius><offset>0</offset></temperature></device><device identifier="08761 0039731" id="17" functionbitmask="2944" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Klimaanlage</name><switch><state>0</state><mode>auto</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>0</power><energy>625024</energy></powermeter><temperature><celsius>135</celsius><offset>0</offset></temperature></device></devicelist>

In both cases the syntax of the XML response is correct with slightly different values.

Good case:

response complete: <devicelist version="1"><device identifier="08761 0005102" id="16" functionbitmask="896" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Kühlschrank</name><switch><state>1</state><mode>manuell</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>350</power><energy>1132377</energy></powermeter><temperature><celsius>210</celsius><offset>0</offset></temperature></device><device identifier="08761 0039731" id="17" functionbitmask="2944" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Klimaanlage</name><switch><state>0</state><mode>auto</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>0</power><energy>625024</energy></powermeter><temperature><celsius>150</celsius><offset>0</offset></temperature></device></devicelist>

Bad case:

response complete: <devicelist version="1"><device identifier="08761 0005102" id="16" functionbitmask="896" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Kühlschrank</name><switch><state>1</state><mode>manuell</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>350</power><energy>1132361</energy></powermeter><temperature><celsius>210</celsius><offset>0</offset></temperature></device><device identifier="08761 0039731" id="17" functionbitmask="2944" fwversion="03.83" manufacturer="AVM" productname="FRITZ!DECT 200"><present>1</present><name>Klimaanlage</name><switch><state>0</state><mode>auto</mode><lock>0</lock><devicelock>0</devicelock></switch><powermeter><power>0</power><energy>625024</energy></powermeter><temperature><celsius>135</celsius><offset>0</offset></temperature></device></devicelist>

But in the bad case the PowerMeterModel object ist null. ...mode=manuell,lock=0],<null>,org.openhab.binding...

set device model: org.openhab.binding.avmfritz.internal.ahamodel.DeviceModel@5ae11065[ain=087610005102,bitmask=896,isDectRepeater=false,isPowermeter=true,isTempSensor=true,isSwitchableOutlet=true,id=16,manufacturer=AVM,productname=FRITZ!DECT 200,fwversion=03.83,present=1,name=Kühlschrank,org.openhab.binding.avmfritz.internal.ahamodel.SwitchModel@499b66b0[state=1,mode=manuell,lock=0],<null>,org.openhab.binding.avmfritz.internal.ahamodel.TemperatureModel@564bc83[celsius=21.0,offset=0.0]]

I don't know how the XML parsing works. Is there an error in the XML parser initialization? Or why is the PowerMeterModel object not created with correct input?

cweitkamp commented 7 years ago

Hey there, I am going to look into this. Thanks for reporting the observed situation. It was posted in the community forum, too (see here). Sometimes I received those NPEs suddenly in a running environment. It runs correctly for several days and then it fails. After a restart problem is gone. My experience with the used XML-parser is not very good, so I have no clue why this happens. I have implemented a fallback in Pull request #1815 which handles the NPEs. But currently there is no sulution for the problem itself.

NorbertHD commented 7 years ago

Thank you for looking into this. I have also looked into the source and I think there are 2 issues.

In /avmfritz/internal/ahamodel/DeviceModel.java line 64 - 68:

58  @XmlElement(name = "present") 
59  private Integer present; 
60   
61  @XmlElement(name = "name") 
62  private String name; 
63   
64  private SwitchModel switchModel; 
65   
66  private PowerMeterModel powermeterModel; 
67 
68  private TemperatureModel temperatureModel;

I think this should be:

        @XmlElement(name = "switch") 
    private SwitchModel switchModel;

        @XmlElement(name = "powermeter")     
    private PowerMeterModel powermeterModel; 

        @XmlElement(name = "temperature") 
    private TemperatureModel temperatureModel;

Also in /avmfritz/internal/hardware/callbacks/FritzAhaUpdateXmlCallback.java on every "execute" a new JAXBContext is created. This is a memory leak. Only one static instance should be created.

See here: (http://stackoverflow.com/questions/3584821/jaxbcontext-newinstance-memory-leak) (https://jaxb.java.net/guide/Performance_and_thread_safety.html)

cweitkamp commented 7 years ago

Thank you for those very helpful advices. I try adding those xml configuration in the DeviceModel.java tonight.

I put refactoring the use of JAXBContext as singleton on my TODO list.

// EDIT: I logged the used memory in my environment and confirm a memory leak.

cweitkamp commented 7 years ago

I just commited a refactored version which uses the JAXBContext as singelton instance. It will be merged with pull request 1887.