From 7a71115e458e7a44ffb51b98d06bb34eb5d4cbdd Mon Sep 17 00:00:00 2001 From: Karel Goderis Date: Wed, 5 Feb 2014 12:26:02 +0100 Subject: [PATCH 1/3] Plugwise : move some binding messages to the DEBUG logging level --- .../org/openhab/binding/plugwise/internal/PlugwiseBinding.java | 2 +- .../main/java/org/openhab/binding/plugwise/internal/Stick.java | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/PlugwiseBinding.java b/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/PlugwiseBinding.java index 19322d94a6a..6e28e55b74f 100644 --- a/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/PlugwiseBinding.java +++ b/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/PlugwiseBinding.java @@ -404,7 +404,7 @@ protected void execute() { // check if the device already exists (via cfg definition of Role Call) if(stick.getDevice(anElement.getId())==null) { - logger.info("The Plugwise device with id {} is not yet defined",anElement.getId()); + logger.debug("The Plugwise device with id {} is not yet defined",anElement.getId()); // check if the config string really contains a MAC address Pattern MAC_PATTERN = Pattern.compile("(\\w{16})"); diff --git a/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/Stick.java b/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/Stick.java index 35b4d5f538b..8fa8d33b418 100644 --- a/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/Stick.java +++ b/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/Stick.java @@ -465,7 +465,7 @@ private void parseAndQueue(ByteBuffer readBuffer) { logger.error("Plugwise protocol CRC error: {} does not match {} in message", new String[] { calculatedCRC, CRC}); } } else { - logger.error("Plugwise protocol header error: {} in message {}", new String[] { protocolHeader, response}); + logger.debug("Plugwise protocol header error: {} in message {}", new String[] { protocolHeader, response}); } } else { logger.error("Plugwise protocol message error: {} ", response); From 4a3abc50dfcb26b23645c24a080f44cd4585ed4d Mon Sep 17 00:00:00 2001 From: Karel Goderis Date: Wed, 12 Feb 2014 13:16:06 +0100 Subject: [PATCH 2/3] Fix a lock() race condition halting the binding Add extensive debugging info/output (to be removed later) Enable stick.retries parameter in openhab.cfg to set max number of retries when sending message on the ZigBee network --- .../plugwise/internal/PlugwiseBinding.java | 12 +- .../binding/plugwise/internal/Stick.java | 132 +++++++++++------- .../binding/plugwise/protocol/Message.java | 10 ++ 3 files changed, 100 insertions(+), 54 deletions(-) diff --git a/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/PlugwiseBinding.java b/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/PlugwiseBinding.java index 6e28e55b74f..63e6eddff7a 100644 --- a/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/PlugwiseBinding.java +++ b/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/PlugwiseBinding.java @@ -62,8 +62,6 @@ public class PlugwiseBinding extends AbstractActiveBinding sendQueue = new ArrayBlockingQueue(maxBufferSize,true); @@ -93,7 +90,10 @@ public class Stick extends PlugwiseDevice implements SerialPortEventListener{ private boolean initialised = false; protected List plugwiseDeviceCache = Collections.synchronizedList(new ArrayList()); private PlugwiseBinding binding; - private int interval = 150 ; + /** default interval for sending messages on the ZigBee network */ + private int interval = 50 ; + /** default maximum number of attempts to send a message */ + private int maxRetries = 1; public Stick(String port, PlugwiseBinding binding) { super("", PlugwiseDevice.DeviceType.Stick, "stick"); @@ -158,11 +158,15 @@ protected PlugwiseDevice getDeviceByName(String name) { public String getPort() { return port; } - + public void setInterval(int interval) { this.interval = interval; } + public void setRetries(int retries) { + this.maxRetries = retries; + } + public boolean isInitialised() { return initialised; } @@ -174,12 +178,12 @@ public boolean isInitialised() { */ @SuppressWarnings("rawtypes") private void initialize() throws PlugwiseInitializationException { - + //Flush the deviceCache if(this.plugwiseDeviceCache!=null) { plugwiseDeviceCache = Collections.synchronizedList(new ArrayList()); } - + // parse ports and if the default port is found, initialized the reader Enumeration portList = CommPortIdentifier.getPortIdentifiers(); while (portList.hasMoreElements()) { @@ -255,7 +259,7 @@ private void initialize() throws PlugwiseInitializationException { .withIdentity("Send-0", "Plugwise") .startNow() .build(); - + try { sched.getListenerManager().addJobListener(new SendJobListener("JobListener-"+job.getKey().toString()), KeyMatcher.keyEquals(job.getKey())); } catch (SchedulerException e1) { @@ -284,7 +288,7 @@ private void initialize() throws PlugwiseInitializationException { .repeatForever() .withIntervalInMilliseconds(50)) .build(); - + try { sched.scheduleJob(job, trigger); } catch (SchedulerException e) { @@ -310,7 +314,7 @@ public void close() { } catch (IOException e) { logger.error("An exception occurred while closing the serial port {} ({})", serialPort,e.getMessage()); } - + initialised = false; } @@ -367,9 +371,10 @@ public void serialEvent(SerialPortEvent event) { public void sendMessage(Message message) { if(message!= null && isInitialised() ) { try { + logger.debug("sendMessage: Stick send message: {}", message.toString()); sendQueue.put(message); } catch (InterruptedException e) { - logger.error("Error sending Plugwise message: {}", message.toHexString()); + logger.error("Error sending Plugwise message: {}", message.toString()); } } } @@ -412,7 +417,7 @@ private void parseAndQueue(ByteBuffer readBuffer) { String calculatedCRC = getCRCFromString(command + sequence + payload); if(calculatedCRC.equals(CRC)) { - logger.debug("Parsing Plugwise protocol data unit: command:{} sequence:{} payload:{}", new String[] { MessageType.forValue(Integer.parseInt(command,16)).toString(), Integer.toString(Integer.parseInt(sequence,16)),payload}); + logger.debug("parseAndQueue: Parsing Plugwise protocol data unit: command:{} sequence:{} payload:{}", new String[] { MessageType.forValue(Integer.parseInt(command,16)).toString(), Integer.toString(Integer.parseInt(sequence,16)),payload}); Message theMessage = null; @@ -448,13 +453,14 @@ private void parseAndQueue(ByteBuffer readBuffer) { theMessage = new PowerInformationResponseMessage(Integer.parseInt(sequence,16), payload); break; default: - logger.debug("Received unrecognized Plugwise protocol data unit: command:{} sequence:{} payload:{}", new String[] { command, Integer.toString(Integer.parseInt(sequence,16)),payload}); + logger.debug("parseAndQueue: Received unrecognized Plugwise protocol data unit: command:{} sequence:{} payload:{}", new String[] { command, Integer.toString(Integer.parseInt(sequence,16)),payload}); break; }; if(theMessage != null) { try { receiveLock.lock(); + logger.debug("parseAndQueue: {} messages before the message ({}) put in the receiveQ",receivedQueue.size(),theMessage.toString()); receivedQueue.put(theMessage); receiveLock.unlock(); } catch (InterruptedException e) { @@ -465,7 +471,7 @@ private void parseAndQueue(ByteBuffer readBuffer) { logger.error("Plugwise protocol CRC error: {} does not match {} in message", new String[] { calculatedCRC, CRC}); } } else { - logger.debug("Plugwise protocol header error: {} in message {}", new String[] { protocolHeader, response}); + logger.debug("parseAndQueue: Plugwise protocol header error: {} in message {}", new String[] { protocolHeader, response}); } } else { logger.error("Plugwise protocol message error: {} ", response); @@ -505,7 +511,7 @@ public boolean processMessage(Message message) { case TIMEOUT: // we put the message back in the queue, without tagging it - logger.error("Timeout sending Plugwise message with sequence number: {}", ((AcknowledgeMessage)message).getSequenceNumber()); + logger.error("Timeout sending Plugwise message : {}", ((AcknowledgeMessage)message).toString()); // traverse the sent Q for the Iterator messageIterator= sentQueue.iterator(); @@ -513,6 +519,7 @@ public boolean processMessage(Message message) { while(messageIterator.hasNext()) { aMessage = messageIterator.next(); if(aMessage.getSequenceNumber() == message.getSequenceNumber()) { + logger.debug("processMessage: timeout : removing a msg from the senTq: {}",aMessage.toString()); sentQueue.remove(aMessage); break; } @@ -521,11 +528,6 @@ public boolean processMessage(Message message) { if(aMessage != null) { //reset the sequence number and put it back in the send Q aMessage.setSequenceNumber(0); - try { - Thread.sleep(3000); - } catch (InterruptedException e) { - logger.error("Error putting plugwise thread to sleep"); - } sendMessage(aMessage); } @@ -660,12 +662,16 @@ public static class SendJob implements Job { public void execute(JobExecutionContext context) throws JobExecutionException { + // get the reference to the Stick JobDataMap dataMap = context.getJobDetail().getJobDataMap(); theStick = (Stick) dataMap.get("Stick"); + // logger.debug("SendJob: Executing Quartz Send Job"); + if(theStick.isInitialised()) { - // loop through the send queue and send out all messages + // loop through the send queue and send out all messages + logger.debug("SendJob: {} messages in the sendQ ",theStick.sendQueue.size()); Message message = theStick.sendQueue.poll(); while(message != null) { sendMessage(message); @@ -674,6 +680,7 @@ public void execute(JobExecutionContext context) } catch (InterruptedException e) { logger.debug("An exception occurred while putting the Plugwise SendJob thread to sleep : {}",e.getMessage()); } + logger.debug("SendJob: in loop: {} messages in the sendQ ",theStick.sendQueue.size()); message = theStick.sendQueue.poll(); } } @@ -681,19 +688,21 @@ public void execute(JobExecutionContext context) private boolean sendMessage(Message message) { if (message != null) { - if(message.getAttempts() < MAX_ATTEMPTS) { + if(message.getAttempts() < theStick.maxRetries) { message.increaseAttempts(); - logger.debug("Sending Plugwise protocol data unit: attempts: {} MAC:{} command:{} sequence:{} full HEX:{}", new String[] { Integer.toString(message.getAttempts()),message.getMAC(),message.getType().toString(), Integer.toString(message.getSequenceNumber()),message.toHexString()}); + logger.debug("sendMessage: Sending Plugwise protocol data unit: attempts: {} MAC:{} command:{} sequence:{} full HEX:{}", new String[] { Integer.toString(message.getAttempts()),message.getMAC(),message.getType().toString(), Integer.toString(message.getSequenceNumber()),message.toHexString()}); String packedString = PROTOCOL_HEADER + message.toHexString() + PROTOCOL_TRAILER; ByteBuffer bytebuffer = ByteBuffer.allocate(packedString.length()); bytebuffer.put(packedString.getBytes()); bytebuffer.rewind(); + logger.debug("sendMessage: Locking the queues"); theStick.queueLock.lock(); try { + logger.debug("sendMessage: Writing message to the outputchannel of the stick : {}",message.toString()); theStick.outputChannel.write(bytebuffer); } catch (IOException e) { logger.error("Error writing '{}' to serial port {}: {}", new String[] { packedString, theStick.port, e.getMessage() }); @@ -703,8 +712,11 @@ private boolean sendMessage(Message message) { Message lastMessage = null; + logger.debug("sendMessage: Entering loop for lastMessage"); + while(lastMessage==null) { + // logger.debug("sendMessage: Locking the Receive queues"); theStick.receiveLock.lock(); Iterator messageIterator= theStick.receivedQueue.iterator(); while(messageIterator.hasNext()) { @@ -713,13 +725,17 @@ private boolean sendMessage(Message message) { if(aMessage.getType().equals(MessageType.ACKNOWLEDGEMENT)) { if(!((AcknowledgeMessage)aMessage).isExtended()) { lastMessage = aMessage; + logger.debug("sendMessage: Removing an ACK from the RecQ: {}",lastMessage.toString()); theStick.receivedQueue.remove(lastMessage); break; } } } + // logger.debug("sendMessage: Unlocking the Receive queues"); theStick.receiveLock.unlock(); } + logger.debug("sendMessage: Exiting loop for lastMessage"); + AcknowledgeMessage ack = (AcknowledgeMessage) lastMessage; @@ -734,12 +750,23 @@ private boolean sendMessage(Message message) { // place the sent message in the sent Q try { + logger.debug("sendMessage: putting message in the senTq : {}",message.toString()); + if(theStick.sentQueue.size()==maxBufferSize) { + // For some @#$@#$ reason plugwise devices, or the Stick, does not send responses + // to Requests. They clog the sentQueue. Let's flush some part of the queue + Message someMessage = theStick.sentQueue.poll(); + logger.debug("Flushing a message from the sentQueue: {}",someMessage); + + } theStick.sentQueue.put(message); + logger.debug("sendMessage: there are now {} msg in the senTq",theStick.sentQueue.size()); + //logger.debug("senTq is now {}",theStick.sentQueue); } catch (InterruptedException e) { - logger.error("Error storing Plugwise message in the sent queue: {}", message.toHexString()); + logger.error("Error storing Plugwise message in the sent queue: {}", message.toString()); } } + logger.debug("sendMessage: Unlocking the queues"); theStick.queueLock.unlock(); return true; @@ -752,30 +779,32 @@ private boolean sendMessage(Message message) { return false; } } - + public class SendJobListener implements JobListener { - private String name; + private String name; + + public SendJobListener(String name) { + this.name = name; + } + + public String getName() { + return name; + } - public SendJobListener(String name) { - this.name = name; - } - - public String getName() { - return name; - } + public void jobToBeExecuted(JobExecutionContext context) { + // do something with the event + } - public void jobToBeExecuted(JobExecutionContext context) { - // do something with the event - } + public void jobWasExecuted(JobExecutionContext context, + JobExecutionException jobException) { - public void jobWasExecuted(JobExecutionContext context, - JobExecutionException jobException) { - // get the reference to the Stick JobDataMap dataMap = context.getJobDetail().getJobDataMap(); Stick theStick = (Stick) dataMap.get("Stick"); - + + // logger.debug("SendJobListener: SJobListeren reschedule a job"); + Scheduler sched = null; try { sched = StdSchedulerFactory.getDefaultScheduler(); @@ -785,7 +814,7 @@ public void jobWasExecuted(JobExecutionContext context, JobDataMap map = new JobDataMap(); map.put("Stick", theStick); - + Stick.counter++; JobDetail job = newJob(SendJob.class) @@ -797,24 +826,24 @@ public void jobWasExecuted(JobExecutionContext context, .withIdentity("Send-"+Stick.counter, "Plugwise") .startNow() .build(); - + try { sched.getListenerManager().addJobListener(new SendJobListener("JobListener-"+job.getKey().toString()), KeyMatcher.keyEquals(job.getKey())); } catch (SchedulerException e1) { logger.error("An exception occured while attaching a Quartz Send Job Listener"); } - + try { sched.scheduleJob(job, trigger); } catch (SchedulerException e) { logger.error("Error scheduling a job with the Quartz Scheduler : {}",e.getMessage()); } - - } - public void jobExecutionVetoed(JobExecutionContext context) { - // do something with the event - } + } + + public void jobExecutionVetoed(JobExecutionContext context) { + // do something with the event + } } @@ -832,8 +861,11 @@ public void execute(JobExecutionContext context) theStick = (Stick) dataMap.get("Stick"); if(theStick.isInitialised()) { + logger.debug("ProcessMessageJob: Locking the queues"); theStick.queueLock.lock(); + logger.debug("ProcessMessageJob: there are {} msg in the receivedQ",theStick.receivedQueue.size()); Message message = theStick.receivedQueue.poll(); + logger.debug("ProcessMessageJob: Unlocking the queues"); theStick.queueLock.unlock(); if(message != null) { @@ -857,6 +889,7 @@ public void execute(JobExecutionContext context) while(messageIterator.hasNext()) { Message aMessage = messageIterator.next(); if(aMessage.getSequenceNumber() == message.getSequenceNumber()) { + logger.debug("execute: removing a msg from the senTq: {}",aMessage.toString()); theStick.sentQueue.remove(aMessage); break; } @@ -949,5 +982,4 @@ public void execute(JobExecutionContext context) } } } - } diff --git a/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/protocol/Message.java b/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/protocol/Message.java index 0dfb20b08e3..c0da2e246b1 100644 --- a/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/protocol/Message.java +++ b/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/protocol/Message.java @@ -50,6 +50,16 @@ public Message( int sequenceNumber, String payLoad) { parsePayLoad(); } + public String toString() { + + return "Plugwise Message [type=" + type.toString()+ + ", MAC="+MAC+ + ", SeqNr="+sequenceNumber+ + ", payload="+payLoad+ + ", retrycount="+retryCount+"]"; + + } + // for messages where we do not care about the MAC address public Message(String payLoad) { this.payLoad = payLoad; From 08a41d1a4fa4edffb61ea50ff1cfb0bc2b562acd Mon Sep 17 00:00:00 2001 From: Karel Goderis Date: Thu, 13 Feb 2014 09:56:12 +0100 Subject: [PATCH 3/3] Plugwise : small improvement to logging --- .../java/org/openhab/binding/plugwise/internal/Stick.java | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/Stick.java b/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/Stick.java index 6e0dddcf481..8db00fed218 100644 --- a/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/Stick.java +++ b/bundles/binding/org.openhab.binding.plugwise/src/main/java/org/openhab/binding/plugwise/internal/Stick.java @@ -474,7 +474,9 @@ private void parseAndQueue(ByteBuffer readBuffer) { logger.debug("parseAndQueue: Plugwise protocol header error: {} in message {}", new String[] { protocolHeader, response}); } } else { - logger.error("Plugwise protocol message error: {} ", response); + if(!response.contains("APSRequestNodeInfo")) { + logger.error("Plugwise protocol message error: {} ", response); + } } } }