Turns out, there was more to it than that. I was seeing the device simply stop sending data for a while, and only a full restart of openhab would fix it.
I was seeing this in the logs:
20:49:43.540 [WARN ] [core.common.registry.AbstractRegistry] - Cannot add "ItemChannelLink" with key "ElectricityMeter_InstantaneousDemand -> eagle200:eagle200_electric_meter:0x0013500100c8adae:InstantaneousDemand". It exists already from provider "GenericItemChannelLinkProvider"! Failed to add a second with the same UID from provider "ManagedItemChannelLinkProvider"!
It didn’t seem to matter, but later, I’d see this:
2019-02-11 21:43:15.038 [vent.ItemStateChangedEvent] - ElectricityMeter_InstantaneousDemand changed from 1.453000 to 1.475000
2019-02-11 21:43:49.394 [temChannelLinkRemovedEvent] - Link 'ElectricityMeter_InstantaneousDemand => eagle200:eagle200_electric_meter:0x0013500100c8adae:InstantaneousDemand' has been removed.
2019-02-11 21:45:42.603 [.ItemChannelLinkAddedEvent] - Link 'ElectricityMeter_InstantaneousDemand-eagle200:eagle200_electric_meter:0x0013500100c8adae:InstantaneousDemand' has been added.
After that remove and add of the links, no more data would be updated.
I don’t know what caused that. It could be I did something that caused a config file reload.
So, I removed the binding, the things, the item, AND the extra link and I tried again. The extra link showed only in the karaf console, and I had to remove it there. It stuck around even after everything else was gone.
Once my config was clear, I reinstalled the addon, added the Eagle thing, and then let it find the Electricity Meter thing. I used PaperUI to create an item connected to the channel I wanted from the Electricity Meter thing.
This time I got no data. A post earlier in this thread made me wonder if there was something going wrong, and when I looked at the list of links, there was no link between the Electricity Meter thing and the item. So I removed the item that PaperUI created one and inserted one manually in a .items file - I used one the first time, so just updated the channel name and put it back.
I’m getting data now. All I have to see is if I keep getting data! Hopefully the extra link is all that was wrong. I have no idea where it came from, though, or how to find it except by prowling around the console and looking at things I’ve never heard of before. The warning got me looking there, and other posts in this thread got me to use an items file instead of the UI to create the item that can be persisted and used in the sitemap!
So far, so good! Hopefully if this bites someone else they’ll be able to sort it out.
UPDATE: Nope, still not right.
I’m seeing the oddest behavior.
Sometimes, the binding works great, and I get data. That’ll run for hours. And then it simply stops updating data. Often a reboot will fix it - I have a nightly reboot of my RPi at 4:37am. But not always.
Here’s my configuration:
Here’s the things, as shown by smarthome:things in karaf. Both were automatically discovered and added via PaperUI:
eagle200:eagle200_electric_meter:0x0013500100c8adae (Type=Thing, Status=ONLINE, Label=Electricity Meter, Bridge=eagle200:eagle200_bridge:6a25dc04)
eagle200:eagle200_bridge:6a25dc04 (Type=Bridge, Status=ONLINE, Label=Eagle 200, Bridge=null)
There is the electric meter, and the bridge. Both have sensible values, and openhab showes them as on-line.
Here’s the thing, also from karaf:
ElectricityMeter_InstantaneousDemand (Type=NumberItem, State=NULL, Label=Current Electric Usage, Category=null, Groups=[ChartData])
The state is NULL, and has stayed that way. Interestingly, when the device fails, the state goes from a sensible number to NULL and then stays NULL.
The link is showing up in karaf as well:
ElectricityMeter_InstantaneousDemand -> eagle200:eagle200_electric_meter:0x0013500100c8adae:InstantaneousDemand
The Item and the link are defined in an items file:
Number ElectricityMeter_InstantaneousDemand "Current Electric Usage [%f kWh]" (ChartData) { channel="eagle200:eagle200_electric_meter:0x0013500100c8adae:InstantaneousDemand" }
When the system runs, and shows a failure, I’ve gotten a bunch more debug information (yay!)
2019-02-14 22:05:24.540 [TRACE] [b.binding.eagle200.discovery.EagleDiscoveryService] - Scanning for energy meters
2019-02-14 22:05:24.808 [TRACE] [penhab.binding.eagle200.handler.Eagle200Connection] - Eagle200 meter HW address: <DeviceList> <Device> <HardwareAddress>0x0013500100c8adae</HardwareAddress> <Manufacturer>Generic</Manufacturer> <ModelId>electric_meter</ModelId> <Protocol>Zigbee</Protocol> <LastContact>0x5c6656a3</LastContact> <ConnectionStatus>Connected</ConnectionStatus> <NetworkAddress>0xffff</NetworkAddress> </Device></DeviceList>
2019-02-14 22:05:24.815 [TRACE] [b.binding.eagle200.discovery.EagleDiscoveryService] - Bridge eagle200:eagle200_bridge:6a25dc04 for device eagle200:eagle200_electric_meter:0x0013500100c8adae is in state ONLINE, scan count 329
2019-02-14 22:05:39.821 [TRACE] [b.binding.eagle200.discovery.EagleDiscoveryService] - Scanning for energy meters
2019-02-14 22:05:40.067 [TRACE] [penhab.binding.eagle200.handler.Eagle200Connection] - Eagle200 meter HW address: <DeviceList> <Device> <HardwareAddress>0x0013500100c8adae</HardwareAddress> <Manufacturer>Generic</Manufacturer> <ModelId>electric_meter</ModelId> <Protocol>Zigbee</Protocol> <LastContact>0x5c6656ac</LastContact> <ConnectionStatus>Connected</ConnectionStatus> <NetworkAddress>0xffff</NetworkAddress> </Device></DeviceList>
2019-02-14 22:05:40.093 [TRACE] [b.binding.eagle200.discovery.EagleDiscoveryService] - Bridge eagle200:eagle200_bridge:6a25dc04 for device eagle200:eagle200_electric_meter:0x0013500100c8adae is in state ONLINE, scan count 330
2019-02-14 22:05:55.100 [TRACE] [b.binding.eagle200.discovery.EagleDiscoveryService] - Scanning for energy meters
2019-02-14 22:05:55.337 [TRACE] [penhab.binding.eagle200.handler.Eagle200Connection] - Eagle200 meter HW address: <DeviceList> <Device> <HardwareAddress>0x0013500100c8adae</HardwareAddress> <Manufacturer>Generic</Manufacturer> <ModelId>electric_meter</ModelId> <Protocol>Zigbee</Protocol> <LastContact>0x5c6656bc</LastContact> <ConnectionStatus>Connected</ConnectionStatus> <NetworkAddress>0xffff</NetworkAddress> </Device></DeviceList>
2019-02-14 22:05:55.346 [TRACE] [b.binding.eagle200.discovery.EagleDiscoveryService] - Bridge eagle200:eagle200_bridge:6a25dc04 for device eagle200:eagle200_electric_meter:0x0013500100c8adae is in state ONLINE, scan count 331
2019-02-14 22:06:10.352 [TRACE] [b.binding.eagle200.discovery.EagleDiscoveryService] - Scanning for energy meters
2019-02-14 22:06:10.691 [TRACE] [penhab.binding.eagle200.handler.Eagle200Connection] - Eagle200 meter HW address: <DeviceList> <Device> <HardwareAddress>0x0013500100c8adae</HardwareAddress> <Manufacturer>Generic</Manufacturer> <ModelId>electric_meter</ModelId> <Protocol>Zigbee</Protocol> <LastContact>0x5c6656cb</LastContact> <ConnectionStatus>Connected</ConnectionStatus> <NetworkAddress>0xffff</NetworkAddress> </Device></DeviceList>
2019-02-14 22:06:10.700 [TRACE] [b.binding.eagle200.discovery.EagleDiscoveryService] - Bridge eagle200:eagle200_bridge:6a25dc04 for device eagle200:eagle200_electric_meter:0x0013500100c8adae is in state ONLINE, scan count 332
2019-02-14 22:06:15.598 [TRACE] [penhab.binding.eagle200.handler.Eagle200Connection] - Eagle200 meter query 0x0013500100c8adae: <Device> <DeviceDetails> <Name>Power Meter</Name> <HardwareAddress>0x0013500100c8adae</HardwareAddress> <NetworkInterface>0xd8d5b9000000fede</NetworkInterface> <Protocol>Zigbee</Protocol> <NetworkAddress>0xffff</NetworkAddress> <Manufacturer>Generic</Manufacturer> <ModelId>electric_meter</ModelId> <LastContact>0x5c6656d3</LastContact> <ConnectionStatus>Connected</ConnectionStatus> </DeviceDetails> <Components> <Component> <HardwareId></HardwareId> <FixedId>0</FixedId> <Name>Main</Name> <Variables> <Variable> <Name>zigbee:InstantaneousDemand</Name> <Value>1.390000</Value> <Units>kW</Units> <Description>Instantaneous Demand</Description> </Variable> <Variable> <Name>zigbee:Multiplier</Name> <Value>1</Value> <Units></Units> <Description>Multiplier applied to demand and summation values</Description> </Variable> <Variable> <Name>zigbee:Divisor</Name> <Value>1000</Value> <Units></Units> <Description>Divisor applied to demand and summation values</Description> </Variable> <Variable> <Name>zigbee:CurrentSummationDelivered</Name> <Value>27168.103000</Value> <Units>kWh</Units> <Description>Summation Delivered to Home</Description> </Variable> <Variable> <Name>zigbee:CurrentSummationReceived</Name> <Value>0.000000</Value> <Units>kWh</Units> <Description>Summation Received from Home</Description> </Variable> <Variable> <Name>zigbee:Price</Name> <Value></Value> <Units></Units> <Description>Price of electricity</Description> </Variable> <Variable> <Name>zigbee:TrailingDigits</Name> <Value></Value> <Units></Units> <Description>Indicates the number of digits to the right of the decimal point</Description> </Variable> <Variable> <Name>zigbee:RateLabel</Name> <Value></Value> <Units></Units> <Description>Active priuce rate label</Description> </Variable> <Variable> <Name>zigbee:Currency</Name> <Value></Value> <Units></Units> <Description>The local unit of currency used in the price field</Description> </Variable> <Variable> <Name>zigbee:PriceTier</Name> <Value></Value> <Units></Units> <Description>The current Price Tier</Description> </Variable> <Variable> <Name>zigbee:PriceStartTime</Name> <Value></Value> <Units></Units> <Description>The time at which the price signal becomes valid</Description> </Variable> <Variable> <Name>zigbee:PriceDuration</Name> <Value></Value> <Units>min</Units> <Description>Amount of time in minutes after the Start Time during which the price signal is valid</Description> </Variable> <Variable> <Name>zigbee:Message</Name> <Value></Value> <Units></Units> <Description>Message from utility to customer</Description> </Variable> <Variable> <Name>zigbee:MessageId</Name> <Value></Value> <Units></Units> <Description>Message unique ID</Description> </Variable> <Variable> <Name>zigbee:MessageStartTime</Name> <Value></Value> <Units></Units> <Description>Start time for current message</Description> </Variable> <Variable> <Name>zigbee:MessageDurationInMinutes</Name> <Value></Value> <Units>min</Units> <Description>Start time for current message</Description> </Variable> <Variable> <Name>zigbee:MessagePriority</Name> <Value></Value> <Units></Units> <Description>Message priority</Description> </Variable> <Variable> <Name>zigbee:MessageConfirmationRequired</Name> <Value></Value> <Units></Units> <Description>Indicates if the message requires user confirmation</Description> </Variable> <Variable> <Name>zigbee:MessageConfirmed</Name> <Value></Value> <Units></Units> <Description>Indicates if the message has received user confirmation</Description> </Variable> <Variable> <Name>zigbee:BlockPeriodNumberOfBlocks</Name> <Value></Value> <Units></Units> <Description></Description> </Variable> <Variable> <Name>zigbee:BlockPeriodConsumption</Name> <Value></Value> <Units>kWh</Units> <Description>The most recent summed value of Energy, Gas or Water delivered and consumed in the premises during the Block Tariff Period</Description> </Variable> <Variable> <Name>zigbee:Block1Price</Name> <Value></Value> <Units>USD/kWh</Units> <Description>The price of Energy, Gas, or Water delivered to the premises at a specific price tier</Description> </Variable> <Variable> <Name>zigbee:Block2Price</Name> <Value></Value> <Units>USD/kWh</Units> <Description>The price of Energy, Gas, or Water delivered to the premises at a specific price tier</Description> </Variable> <Variable> <Name>zigbee:Block3Price</Name> <Value></Value> <Units>USD/kWh</Units> <Description>The price of Energy, Gas, or Water delivered to the premises at a specific price tier</Description> </Variable> <Variable> <Name>zigbee:Block4Price</Name> <Value></Value> <Units>USD/kWh</Units> <Description>The price of Energy, Gas, or Water delivered to the premises at a specific price tier</Description> </Variable> <Variable> <Name>zigbee:Block5Price</Name> <Value></Value> <Units>USD/kWh</Units> <Description>The price of Energy, Gas, or Water delivered to the premises at a specific price tier</Description> </Variable> <Variable> <Name>zigbee:Block6Price</Name> <Value></Value> <Units>USD/kWh</Units> <Description>The price of Energy, Gas, or Water delivered to the premises at a specific price tier</Description> </Variable> <Variable> <Name>zigbee:Block7Price</Name> <Value></Value> <Units>USD/kWh</Units> <Description>The price of Energy, Gas, or Water delivered to the premises at a specific price tier</Description> </Variable> <Variable> <Name>zigbee:Block8Price</Name> <Value></Value> <Units>USD/kWh</Units> <Description>The price of Energy, Gas, or Water delivered to the premises at a specific price tier</Description> </Variable> <Variable> <Name>zigbee:Block1Threshold</Name> <Value></Value> <Units>kWh</Units> <Description>the block threshold values for a given period (typically the billing cycle)</Description> </Variable> <Variable> <Name>zigbee:Block2Threshold</Name> <Value></Value> <Units>kWh</Units> <Description>the block threshold values for a given period (typically the billing cycle)</Description> </Variable> <Variable> <Name>zigbee:Block3Threshold</Name> <Value></Value> <Units>kWh</Units> <Description>the block threshold values for a given period (typically the billing cycle)</Description> </Variable> <Variable> <Name>zigbee:Block4Threshold</Name> <Value></Value> <Units>kWh</Units> <Description>the block threshold values for a given period (typically the billing cycle)</Description> </Variable> <Variable> <Name>zigbee:Block5Threshold</Name> <Value></Value> <Units>kWh</Units> <Description>the block threshold values for a given period (typically the billing cycle)</Description> </Variable> <Variable> <Name>zigbee:Block6Threshold</Name> <Value></Value> <Units>kWh</Units> <Description>the block threshold values for a given period (typically the billing cycle)</Description> </Variable> <Variable> <Name>zigbee:Block7Threshold</Name> <Value></Value> <Units>kWh</Units> <Description>the block threshold values for a given period (typically the billing cycle)</Description> </Variable> <Variable> <Name>zigbee:Block8Threshold</Name> <Value></Value> <Units>kWh</Units> <Description>the block threshold values for a given period (typically the billing cycle)</Description> </Variable> <Variable> <Name>zigbee:BlockPeriodStart</Name> <Value></Value> <Units></Units> <Description>The start time of the current block tariff period</Description> </Variable> <Variable> <Name>zigbee:BlockPeriodDuration</Name> <Value></Value> <Units>min</Units> <Description>The current block tariff period duration in minutes</Description> </Variable> <Variable> <Name>zigbee:BlockThresholdMultiplier</Name> <Value></Value> <Units></Units> <Description>Provides a value to be multiplied against Threshold attributes</Description> </Variable> <Variable> <Name>zigbee:BlockThresholdDivisor</Name> <Value></Value> <Units></Units> <Description>Provides a value to divide the result of applying the threshold multiplier attribute to Block Threshold values</Description> </Variable> <Variable> <Name>zigbee:BillingPeriodStart</Name> <Value></Value> <Units></Units> <Description>The start time of the current billing period</Description> </Variable> <Variable> <Name>zigbee:BillingPeriodDuration</Name> <Value></Value> <Units>min</Units> <Description>The current billing period duration in minutes</Description> </Variable> </Variables> </Component> </Components></Device>
It looks like it scans three times, then does a query, which returns what looks like sensible data. You can see it’s found the InstantaneousDemand item that I’m linking to. Here’s an excerpt with carriage returns:
<Variable>
<Name>zigbee:InstantaneousDemand</Name>
<Value>1.390000</Value>
<Units>kW</Units>
<Description>Instantaneous Demand</Description>
</Variable>
That seems to be a sensible value to me, but I don’t know for sure.
When the values are being read, an ItemStateChangedEvent is logged, which records the old and the new value. When things don’t work, I don’t see that.
I don’t know why it works for a while, and then stops. And why a restart fixes it. Sometimes. I haven’t found any notable differences or other errors when it’s working versus when it is not.
After a restart, I see the same pattern of discovery and then a full query to the meter. The behaviors look the same in the detailed logs, except that I get the updates:
2019-02-14 22:17:36.674 [vent.ItemStateChangedEvent] - ElectricityMeter_InstantaneousDemand changed from NULL to 1.368000
Those will keep going for a while… hours, probably. And then it’s just stuck again.
More information. More information. Last night I left debugging up very high and found this in the logs:
2019-02-15 02:08:10.412 [TRACE] [b.binding.eagle200.discovery.EagleDiscoveryService] - Scanning for energy meters
2019-02-15 02:08:45.518 [WARN ] [b.binding.eagle200.discovery.EagleDiscoveryService] - connection to Eagle failed, stopping device scan. Fix network or configuration: No route to host (Host unreachable)
2019-02-15 02:08:45.521 [WARN ] [nhab.binding.eagle200.handler.Eagle200MeterHandler] - connection to Eagle200 caused error
java.net.NoRouteToHostException: No route to host (Host unreachable)
at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:?]
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:?]
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:?]
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:?]
at java.net.Socket.connect(Socket.java:589) ~[?:?]
at java.net.Socket.connect(Socket.java:538) ~[?:?]
at sun.net.NetworkClient.doConnect(NetworkClient.java:180) ~[?:?]
at sun.net.www.http.HttpClient.openServer(HttpClient.java:463) ~[?:?]
at sun.net.www.http.HttpClient.openServer(HttpClient.java:558) ~[?:?]
at sun.net.www.http.HttpClient.<init>(HttpClient.java:242) ~[?:?]
at sun.net.www.http.HttpClient.New(HttpClient.java:339) ~[?:?]
at sun.net.www.http.HttpClient.New(HttpClient.java:357) ~[?:?]
at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1220) ~[?:?]
at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1156) ~[?:?]
at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1040) ~[?:?]
at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1038) ~[?:?]
at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:782) ~[?:?]
at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1037) ~[?:?]
at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:984) ~[?:?]
at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1334) ~[?:?]
at sun.net.www.protocol.http.HttpURLConnection.access$100(HttpURLConnection.java:91) ~[?:?]
at sun.net.www.protocol.http.HttpURLConnection$8.run(HttpURLConnection.java:1301) ~[?:?]
at sun.net.www.protocol.http.HttpURLConnection$8.run(HttpURLConnection.java:1299) ~[?:?]
at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:782) ~[?:?]
at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1298) ~[?:?]
at org.openhab.binding.eagle200.handler.Eagle200Connection.doPost(Eagle200Connection.java:81) ~[24:org.openhab.binding.eagle200:0.0.7.201807012222]
at org.openhab.binding.eagle200.handler.Eagle200Connection.queryMeter(Eagle200Connection.java:108) ~[24:org.openhab.binding.eagle200:0.0.7.201807012222]
at org.openhab.binding.eagle200.handler.Eagle200MeterHandler$1.run(Eagle200MeterHandler.java:73) [24:org.openhab.binding.eagle200:0.0.7.201807012222]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
I don’t know what could cause a network problem with the device; it’s on wired Ethernet, connected to the same network that the openhab server is. I don’t know if one of my switches flaked for a moment, or if the device was rebooting itself or what.
After this, the discovery of the meter stopped. The queries of the meter kept going, though, and updates to the item continued.
At 4:37am, via a Cron job, the host rebooted.
The logs show the binding loading and starting normally, and it’s doing the queries to the Eagle… but there are no updates being made to the item. I do not have any idea why not!
Updated to add:
I’m still seeing the binding go silent. I’ve instrumented it with a watchdog rule that restarts the binding if it sees five minutes without any updates. There’s two extra items; one is a switch with an expire on it that gets turned ON every time data comes in, and the other is a “Loader”, which is what the binding actually updates. A rule on the loader cause it to update the actual item I’m using for the data, then reset the timer, and reset itself to UNDEF. It resets itself to undef so that any value coming in causes a change, so it should update once a minute. Hopefully this will get me data through the night!