/**
* Copyright (c) 2010-2013, openHAB.org and others.
*
* All rights reserved. This program and the accompanying materials
* are made available under the terms of the Eclipse Public License v1.0
* which accompanies this distribution, and is available at
* http://www.eclipse.org/legal/epl-v10.html
*/
package org.openhab.binding.insteonplm;
import java.util.Collection;
import java.util.Dictionary;
import java.util.Enumeration;
import java.util.HashMap;
import java.util.HashSet;
import java.util.Iterator;
import java.util.Map;
import java.util.Map.Entry;
import org.openhab.binding.insteonplm.internal.device.DeviceFeature;
import org.openhab.binding.insteonplm.internal.device.DeviceFeatureListener;
import org.openhab.binding.insteonplm.internal.device.DeviceType;
import org.openhab.binding.insteonplm.internal.device.DeviceTypeLoader;
import org.openhab.binding.insteonplm.internal.device.InsteonAddress;
import org.openhab.binding.insteonplm.internal.device.InsteonDevice;
import org.openhab.binding.insteonplm.internal.device.InsteonDevice.DeviceStatus;
import org.openhab.binding.insteonplm.internal.device.RequestQueueManager;
import org.openhab.binding.insteonplm.internal.driver.Driver;
import org.openhab.binding.insteonplm.internal.driver.DriverListener;
import org.openhab.binding.insteonplm.internal.driver.ModemDBEntry;
import org.openhab.binding.insteonplm.internal.driver.Poller;
import org.openhab.binding.insteonplm.internal.message.Msg;
import org.openhab.binding.insteonplm.internal.message.MsgListener;
import org.openhab.core.binding.AbstractActiveBinding;
import org.openhab.core.binding.BindingProvider;
import org.openhab.core.types.Command;
import org.osgi.service.cm.ConfigurationException;
import org.osgi.service.cm.ManagedService;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
/**
* This class represents the actual implementation of the binding, and controls the high level flow
* of messages to and from the InsteonModem.
*
* Writing this binding has been an odyssey through the quirks of the Insteon protocol
* and Insteon devices. A substantial redesign was necessary at some point along the way.
* Here are some of the hard learned lessons that should be considered by anyone who wants
* to re-architect the binding:
*
* 1) The entries of the link database of the modem are not reliable. The category/subcategory entries in
* particular have junk data. Forget about using the modem database to generate a list of devices.
* The database should only be used to verify that a device has been linked.
*
* 2) Querying devices for their product information does not work either. First of all, battery operated devices
* (and there are a lot of those) have their radio switched off, and may generally not respond to product
* queries. Even main stream hardwired devices sold presently (like the 2477s switch and the 2477d dimmer)
* don't even have a product ID. Although supposedly part of the Insteon protocol, we have yet to
* encounter a device that would cough up a product id when queried, even among very recent devices. They
* simply return zeros as product id. Lesson: forget about querying devices to generate a device list.
*
* 3) Polling is a thorny issue: too much traffic on the network, and messages will be dropped left and right,
* and not just the poll related ones, but others as well. In particular sending back-to-back messages
* seemed to result in the second message simply never getting sent, without flow control back pressure
* (NACK) from the modem. For now the work-around is to space out the messages upon sending, and
* in general poll as infrequently as acceptable.
*
* 4) Instantiating and tracking devices when reported by the modem (either from the database, or when
* messages are received) leads to complicated state management because there is no guarantee at what
* point (if at all) the binding configuration will be available. It gets even more difficult when
* items are created, destroyed, and modified while the binding runs.
*
* For the above reasons, devices are only instantiated when they are referenced by binding information.
* As nice as it would be to discover devices and their properties dynamically, we have abandoned that
* path because it had led to a complicated and fragile system which due to the technical limitations
* above was inherently squirrely.
*
*
* @author Bernd Pfrommer
* @author Daniel Pfrommer
* @since 1.5.0
*/
public class InsteonPLMActiveBinding
extends AbstractActiveBinding<InsteonPLMBindingProvider>
implements ManagedService {
private static final Logger logger = LoggerFactory.getLogger(InsteonPLMActiveBinding.class);
private Driver m_driver = null;
private HashMap<InsteonAddress, InsteonDevice> m_devices = null; // list of all configured devices
private HashMap<String, String> m_config = new HashMap<String, String>();
private PortListener m_portListener = new PortListener();
private long m_devicePollInterval = 300000L;
private long m_deadDeviceTimeout = -1L;
private long m_refreshInterval = 600000L;
private int m_messagesReceived = 0;
private boolean m_isActive = false; // state of binding
private boolean m_hasInitialItemConfig = false;
/**
* Constructor
*/
public InsteonPLMActiveBinding() {
m_driver = new Driver();
m_devices = new HashMap<InsteonAddress, InsteonDevice>();
}
/**
* Inherited from AbstractBinding. This method is invoked by the framework whenever
* a command is coming from openhab, i.e. a switch is flipped via the GUI or other
* controls. The binding translates this openhab command into a message to the modem.
* {@inheritDoc}
*/
@Override
public void internalReceiveCommand(String itemName, Command command) {
logger.info("Item: {} got command {}", itemName, command);
if(!(isProperlyConfigured() && m_isActive)) {
logger.debug("not ready to handle commands yet, returning.");
return;
}
boolean commandHandled = false;
for (InsteonPLMBindingProvider provider : providers) {
if (provider.providesBindingFor(itemName)) {
commandHandled = true;
InsteonPLMBindingConfig c = provider.getInsteonPLMBindingConfig(itemName);
if (c == null) {
logger.warn("could not find config for item {}", itemName);
} else {
sendCommand(c, command);
}
}
}
if (!commandHandled)
logger.warn("No converter found for item = {}, command = {}, ignoring.",
itemName, command.toString());
}
/**
* Inherited from AbstractBinding.
* Activates the binding. There is nothing we can do at this point
* if we don't have the configuration information, which usually comes
* in later, when updated() is called.
* {@inheritDoc}
*/
@Override
public void activate() {
logger.debug("activating binding");
if (isProperlyConfigured() && !m_isActive) {
initialize();
}
m_isActive = true;
}
/**
* Inherited from AbstractBinding. Deactivates the binding.
* The Controller is stopped and the serial interface is closed as well.
* {@inheritDoc}
*/
@Override
public void deactivate() {
logger.debug("deactivating binding!");
shutdown();
m_isActive = false;
}
/**
* Inherited from AbstractActiveBinding.
* {@inheritDoc}
*/
@Override
protected String getName() {
return "InsteonPLM";
}
/**
* Inherited from AbstractActiveBinding.
* Periodically called by the framework to execute a refresh of the binding.
* {@inheritDoc}
*/
@Override
protected void execute() {
logDeviceStatistics();
}
/**
* Inherited from AbstractActiveBinding.
* Returns the refresh interval (time between calls to execute()) in milliseconds.
* {@inheritDoc}
*/
@Override
protected long getRefreshInterval() {
return m_refreshInterval;
}
/**
* Inherited from AbstractActiveBinding.
* This method is called by the framework whenever there are changes to
* a binding configuration.
* @param provider the binding provider where the binding has changed
* @param itemName the item name for which the binding has changed
*/
@Override
public void bindingChanged(BindingProvider provider, String itemName) {
super.bindingChanged(provider, itemName);
m_hasInitialItemConfig = true; // hack around openHAB bug
InsteonPLMBindingConfig c =
((InsteonPLMBindingProvider)provider).getInsteonPLMBindingConfig(itemName);
logger.debug("item {} binding changed: {}", String.format("%-30s", itemName), c);
if (c == null) {
// Item has been removed. This condition is also found when *any*
// change to the items file is made: the items are first removed (c == null),
// and then added anew.
removeFeatureListener(itemName);
} else {
InsteonDevice dev = getDevice(c.getAddress());
if (dev == null) {
dev = makeNewDevice(c);
}
addFeatureListener(dev, itemName, c);
}
}
/**
* Inherited from the ManagedService interface. This method is called whenever the configuration
* is updated. This could be signaling that e.g. the port has changed etc.
* {@inheritDoc}
*/
@Override
public void updated(Dictionary<String, ?> config) throws ConfigurationException {
HashMap<String, String> newConfig = new HashMap<String, String>();
if (config == null) {
logger.debug("seems like our configuration has been erased, will reset everything!");
} else {
// turn config into new HashMap
for (Enumeration<String> e = config.keys(); e.hasMoreElements();) {
String key = e.nextElement();
String value = config.get(key).toString();
newConfig.put(key, value);
}
}
if (newConfig.entrySet().equals(m_config.entrySet())) {
logger.debug("config has not changed, done.");
return;
}
m_config = newConfig;
// configuration has changed
if (m_isActive) {
if (isProperlyConfigured()) {
logger.debug("global binding config has changed, resetting.");
shutdown();
} else {
logger.debug("global binding config has arrived.");
}
}
long deadDeviceCount = 10;
if (m_config.containsKey("refresh")) {
m_refreshInterval = Integer.parseInt(m_config.get("refresh"));
logger.info("refresh interval set to {}s", m_refreshInterval / 1000);
}
if (m_config.containsKey("device_dead_count")) {
deadDeviceCount = s_parseLong(m_config.get("device_dead_count"), 2L, 100000L);
logger.info("device_dead_count set to {} per config file", deadDeviceCount);
}
if (m_config.containsKey("poll_interval")) {
m_devicePollInterval = s_parseLong(m_config.get("poll_interval"), 5000L, 3600000L);
logger.info("poll interval set to {} per config file", m_devicePollInterval);
}
if (m_config.containsKey("more_devices")) {
String fileName = m_config.get("more_devices");
try {
DeviceTypeLoader.s_instance().loadDeviceTypesXML(fileName);
logger.info("read additional device definitions from {}", fileName);
} catch (Exception e) {
logger.error("error reading additional devices from {}", fileName, e);
}
}
m_deadDeviceTimeout = m_devicePollInterval * deadDeviceCount;
logger.info("dead device timeout set to {}s", m_deadDeviceTimeout / 1000);
logger.debug("configuration update complete!");
setProperlyConfigured(true);
if (m_isActive) {
initialize();
}
if (!m_hasInitialItemConfig) triggerBindingChangedCalls();
return;
}
/**
* HACK around openHAB synchronization issues that don't show
* up in the IDE environment, but when running as packaged bundle:
* The InsteonPLMGenericBindingProvider is instantiated *before*
* the InsteonPLMActiveBinding. This means: the binding provider parses
* all the configuration strings, but bindingChanged() in the actual
* binding is not called, because the binding is not even instantiated
* at that point. Later when the binding is active, it has to artificially
* trigger these calls.
*/
private void triggerBindingChangedCalls() {
for (InsteonPLMBindingProvider provider : providers) {
Collection<String> items = provider.getItemNames();
for (Iterator<String> item = items.iterator(); item.hasNext();) {
String itemName = item.next();
bindingChanged(provider, itemName);
}
}
}
/**
* Initialize the binding: initialize the driver etc
*/
private void initialize() {
logger.debug("initializing...");
HashSet<String> ports = new HashSet<String>();
//Initialize ports
for (Map.Entry<String, String> e : m_config.entrySet()) {
String name = e.getKey();
String port = e.getValue();
if (ports.contains(port)) {
logger.warn("port {} {} already in use, check config!", name, port);
continue;
}
logger.info("config: {} -> {}", name, port);
if (name.startsWith("port_")) {
m_driver.addPort(name, port);
m_driver.addMsgListener(m_portListener, port);
}
}
m_driver.setDriverListener(m_portListener);
m_driver.startAllPorts();
switch (m_driver.getNumberOfPorts()) {
case 0:
logger.error("initialization complete, but found no ports!");
break;
case 1:
logger.debug("initialization complete, found 1 port!");
break;
case 2:
logger.warn("initialization complete, found {} ports.",
m_driver.getNumberOfPorts());
break;
}
}
/**
* Clean up all state.
*/
private void shutdown() {
logger.debug("shutting down binding");
m_driver.stopAllPorts();
m_devices.clear();
RequestQueueManager.s_destroyInstance();
Poller.s_instance().stop();
}
/**
* Send command to insteon device
* @param c item binding configuration
* @param command The command to be sent
*/
private void sendCommand(InsteonPLMBindingConfig c, Command command) {
InsteonDevice dev = getDevice(c.getAddress());
if (dev == null) {
logger.warn("no device found with insteon address {}", c.getAddress());
return;
}
dev.processCommand(m_driver, c, command);
}
/**
* Helper method to find a device by address
* @param aAddr the insteon address to search for
* @return reference to the device, or null if not found
*/
private InsteonDevice getDevice(InsteonAddress aAddr) {
if (aAddr == null) return null;
return m_devices.get(aAddr);
}
/**
* Finds the device that a particular item was bound to, and removes the
* item as a listener
* @param aItem The item (FeatureListener) to remove from all devices
*/
private void removeFeatureListener(String aItem) {
synchronized (m_devices) {
for (Iterator<Entry<InsteonAddress, InsteonDevice>> it = m_devices.entrySet().iterator();
it.hasNext(); ) {
InsteonDevice dev = it.next().getValue();
boolean removedListener = dev.removeFeatureListener(aItem);
if (removedListener) {
logger.trace("removed feature listener {} from dev {}", aItem, dev);
}
if (!dev.hasAnyListeners()) {
Poller.s_instance().stopPolling(dev);
it.remove();
logger.trace("removing unreferenced {}", dev);
if (m_devices.isEmpty()) {
logger.debug("all devices removed!", dev);
}
}
}
}
}
/**
* Creates a new insteon device for a given product key
* @param aConfig The binding configuration parameters, needed to make device.
* @return Reference to the new device that has been created
*/
private InsteonDevice makeNewDevice(InsteonPLMBindingConfig aConfig) {
String prodKey = aConfig.getProductKey();
DeviceType dt = DeviceTypeLoader.s_instance().getDeviceType(prodKey);
if (dt == null) {
logger.error("unknown product key: {} for config: {}." +
" Add definition to xml file and try again", prodKey, aConfig);
return null;
}
InsteonDevice dev = InsteonDevice.s_makeDevice(dt);
dev.setAddress(aConfig.getAddress());
dev.setDriver(m_driver);
dev.addPort(m_driver.getDefaultPort());
if (!dev.hasValidPollingInterval()) {
dev.setPollInterval(m_devicePollInterval);
}
if (m_driver.isModemDBComplete() && dev.getStatus() != DeviceStatus.POLLING) {
int ndev = checkIfInModemDatabase(dev);
if (dev.hasModemDBEntry()) {
dev.setStatus(DeviceStatus.POLLING);
Poller.s_instance().startPolling(dev, ndev);
}
}
synchronized (m_devices) {
m_devices.put(aConfig.getAddress(), dev);
}
return (dev);
}
/**
* Checks if a device is in the modem link database, and, if the database
* is complete, logs a warning if the device is not present
* @param dev The device to search for in the modem database
* @return number of devices in modem database
*/
private int checkIfInModemDatabase(InsteonDevice dev) {
InsteonAddress addr = dev.getAddress();
HashMap<InsteonAddress, ModemDBEntry> dbes = m_driver.lockModemDBEntries();
if (dbes.containsKey(addr)) {
if (!dev.hasModemDBEntry()) {
logger.info("device {} found in the modem database!", addr);
dev.setHasModemDBEntry(true);
}
} else {
if (m_driver.isModemDBComplete()) {
logger.warn("device {} not found in the modem database. Did you forget to link?", addr);
}
}
int ndev = dbes.size();
m_driver.unlockModemDBEntries();
return ndev;
}
/**
* Adds a feature listener (i.e. item to a feature of a device)
* @param aDev The device to add the feature listener
* @param aItemName The name of the item (needed for logging and later lookups)
* @param aConfig The binding configuration for the item
*/
private void addFeatureListener(InsteonDevice aDev, String aItemName,
InsteonPLMBindingConfig aConfig) {
if (aDev == null) {
return;
}
DeviceFeature f = aDev.getFeature(aConfig.getFeature());
if (f == null) {
logger.error("item {} references unknown feature: {}, item disabled!", aItemName, aConfig.getFeature());
return;
}
DeviceFeatureListener fl = new DeviceFeatureListener(aItemName, eventPublisher);
fl.setParameters(aConfig.getParameters());
f.addListener(fl);
}
/**
* Handles messages that come in from the ports.
* Will only process one message at a time.
*/
private class PortListener implements MsgListener, DriverListener {
/**
* {@inheritDoc}
*/
@Override
public void msg(Msg msg, String fromPort) {
if (msg.isEcho() || msg.isPureNack()) return;
m_messagesReceived++;
logger.debug("got msg: {}", msg);
InsteonAddress toAddr = msg.getAddr("toAddress");
if (!msg.isBroadcast() && !m_driver.isMsgForUs(toAddr)) {
// not for one of our modems, do not process
return;
}
InsteonAddress fromAddr = msg.getAddr("fromAddress");
if (fromAddr == null) {
logger.debug("invalid fromAddress, ignoring msg {}", msg);
return;
}
synchronized (m_devices) {
InsteonDevice dev = getDevice(fromAddr);
if (dev == null) {
logger.debug("dropping message from unknown device with address {}", fromAddr);
} else {
dev.handleMessage(fromPort, msg);
}
}
}
/**
* {@inheritDoc}
*/
@Override
public void driverCompletelyInitialized() {
HashMap<InsteonAddress, ModemDBEntry> dbes = m_driver.lockModemDBEntries();
logger.info("modem database has {} entries!", dbes.size());
if (dbes.isEmpty()) {
logger.warn("the modem link database is empty!");
}
for (InsteonAddress k : dbes.keySet()) {
logger.debug("modem db entry: {}", k);
}
synchronized (m_devices) {
for (InsteonDevice dev : m_devices.values()) {
InsteonAddress a = dev.getAddress();
if (!dbes.containsKey(a)) {
logger.warn("device {} not found in the modem database. Did you forget to link?", a);
} else {
if (!dev.hasModemDBEntry()) {
logger.info("device {} found in the modem database!", a);
dev.setHasModemDBEntry(true);
}
if (dev.getStatus() != DeviceStatus.POLLING) {
Poller.s_instance().startPolling(dev, dbes.size());
}
}
}
}
m_driver.unlockModemDBEntries();
}
}
private void logDeviceStatistics() {
logger.info(String.format("devices: %3d configured, %3d polling, msgs received: %5d",
m_devices.size(), Poller.s_instance().getSizeOfQueue(), m_messagesReceived));
m_messagesReceived = 0;
synchronized (m_devices) {
for (InsteonDevice dev : m_devices.values()) {
if (dev.isModem()) continue;
if (m_deadDeviceTimeout > 0 &&
dev.getPollOverDueTime() > m_deadDeviceTimeout) {
logger.info("device {} has not responded to polls for {} sec", dev.toString(),
dev.getPollOverDueTime() / 3600);
}
}
}
}
private static long s_parseLong(String pi, long min, long max) {
long t = Long.parseLong(pi);
t = Math.max(t, min);
t = Math.min(t, max);
return t;
}
}