Serial data source stops receiving data after a period of time.

mattonfarm

Hi Joel,
I have had a look thru the logs and there is nothing related to the serial port source. It is all related to the persistent sync.
There is one serial port installed - a USB to TTL converter connected internally.
I have a serial data source and a scripting data source which runs every minute and simply updates a serial data point, which in turn sends a message to the wireless radio to keep it on the correct channel (in case the radio resets).
I am also running the persistent TCP publisher.

I have added the internal data source you posted.
It didn't fall over last night but it's only a matter of time.

Cheers,
Matt.

mattonfarm

Hi Joel,
The serial port data source stopped working at around 23:00 last night. I have attached an Excel spreadsheet of the internal data points you asked me to monitor.
It looks like there was a sudden drop in active threads about the time it stopped.

Regards,
Matt.

Attachment: download link

JoelHaggar

That all looks pretty normal. I didn't see the drop you mentioned. Hopefully tomorrow we'll have a tool for monitoring the serial ports so we can start to see what's going on.

Joel.

mattonfarm

The thread count went from around 27 active to 23 right about when the serial port data stopped. This could indicate the serial port system crashing.

Cheers,
Matt.

Attachment: download link

JoelHaggar

We are working on some improvements to the serial data source now. Can you give us an JSON export of your data source so we can see your exact use case?

Thanks,
Joel.

mattonfarm

Hi Joel,
I have attached the JSON for the serial data source.
Thanks for helping me with this.
Matt.

Attachment: download link

terrypacker

mattonfarm,

I'm one of the developers for Infinite Automation and have put together a beta version for you to try. This version will create rolling logs for the IO received in addition to several other new approaches to the internals for the serial port handling. The logs will be in the mango logs folder prefixed with 'serial-'. There is also a large number of debug logging statements that have been added to the serial communications layer. To enable them just add this to your log4j configuration file:


 &lt;category name="com.infiniteautomation.serial"&gt;&lt;level value="debug"/&gt;&lt;/category&gt;

I have not changed the version number for this module because this is a one-off version and if it works I will roll it into our main codebase.

Thanks for giving this a try and let me know how it works out.

Terry

Attachment: download link

mattonfarm

Thanks Terry,
I'll load it up and let you know how it goes.

Matt.

mattonfarm

Hi Terry,
I am getting an error saying String index out of range:1 when I start the data source. This happens with a new serial data source as well as the original.

Matt.

terrypacker

mattonfarm,

Sorry about that. I had some code in that version to test it on my specific messages (long story but has to do with converting HEX Strings to bytes for Modbus, a feature that will be in the next module release).

Something to consider in your situation is if you are actually getting all of the message out of the Regex matching buffer. This can be seen via the debug logging message:


DEBUG 2014-08-07 08:55:10,086 (com.infiniteautomation.serial.rt.SerialDataSourceRT.serialEvent:275) - Buffer after read: 0103020000b844

If old messages are being tacked onto the end in an ever-growing fashion you need to review your Regex matching. There is some beta code in there now that will ensure that buffer never grows beyond 10k, but if it gets that big things will start to slow down. In the next release of the module there will be a way to set the maximum expected message size and ensure the data source runs efficiently.

Attachment: download link

mattonfarm

Thanks Terry. What you have done should help immensely.
I think a maximum message size option would really help reliability.

Cheers,
Matt.

mattonfarm

Hi Terry,
I think there is still an issue with the new module when writing data to the serial port. When I try to set one of my output points I get the string index out of range:1 message.
Messages from the serial port seem to be working though.

Matt.

mattonfarm

Hi Terry,
I have done some testing and it seems like the new serial port module is less reliable than the old, failing after an hour or so.
I have attached a snippit of the last of the logfile when it failed.
Multiple data points are contained in the buffer when the data source crashes. I wonder if this is the cause?
The buffer doesn't ever get very large but sometimes there are multiple terminated strings waiting to be processed.
I have tried changing my regex to clear the buffer of any '\r' terminated strings which do not fit a data point string (such as debug messages from the wireless microcontroller). It hasn't changed anything.

Matt.

Attachment: download link

terrypacker

Matt,

Thanks for the logs, I'll take some time to go through them later today or tomorrow. As for the problem with setting the point, I've found the bug and will get that out within a similar time frame.

Terry

terrypacker

Matt,

After looking at the log it appears that you are receiving messages that do not end in the '\r' terminator. Is this correct? From your previous post of the JSON config it seems you have the terminator set to '\r'.

If so that will make using this specific data source very difficult. The data source needs to have discrete messages to be able to use the regex matching effectively. The data source will hold all incoming data in a buffer until it sees the terminator, then it attempts to do matching on that. This means that if messages are received without the terminator they are held in the buffer until the terminator is found and then your regex matching is being done on all previous messages in addition to the recently received message with the terminator. I think this is why the datasource is appearing to 'hang', it is actually trying to do complex matching on long strings.

Another point is that it appears that your termination character is located inside some messages, this again will be a problem because the message will be assumed complete and matching will be done on a partial message. I may be wrong on this because of the way the logging is done it's impossible to see the message boundaries.

I've coded up another version of the module which will be more robust in handling this scenario but if what I am seeing is correct I don't think this will be a very effective solution to your problem. If I'm correct let me know and we can discuss other potential solutions. I've also added some additional logging that will show us the actual UTF8 string that is being matched on when matches are being performed.

Thanks,
Terry

Attachment: download link

mattonfarm

Hi Terry,
All messages end with a '\r' terminator so that should be ok. I have had a look at the last message in the log and it looks like this:

CL241.207T1=-99.90
CL241.207T2=-99.90
CL241.207T3=-99.90
CL241.207T4=-99.90
CL241.207T5=-99.90
CL241.207I1=0.0

Each line is terminated with '\r'.
The problem could be that Mango has picked this up as a single message block, rather than 6 different strings.
There are blank '\r' characters at the beginning and end of this block. I wonder if that is what is causing it to crash?
It seems like the data source is trying to process the data string before the termination character is found.

I'll load up the new module and let you know how I get on. I must admit, it is quite hard to see what is happening when everything is logged in hex.

Regards,
Matt.

mattonfarm

Hi Terry,
It seems like occasionally the '\r' character is not being extracted from the buffer.
Here is an example from the logs:

DEBUG 2014-08-11 13:24:58,217 (com.infiniteautomation.serial.rt.SerialDataSourceRT.matchPointValues:316) - Message matched regex: (([A-Z][A-Z][0-9]+.[0-9]+[a-zA-Z0-9]+=).\r)|(.\r)
DEBUG 2014-08-11 13:24:58,218 (com.infiniteautomation.serial.rt.SerialDataSourceRT.matchPointValues:320) - Point Identified: null
DEBUG 2014-08-11 13:24:58,222 (com.infiniteautomation.io.serial.SerialPortProxyEventTask.run:29) - Running event created at: 1407720298215
DEBUG 2014-08-11 13:24:58,223 (com.infiniteautomation.serial.rt.SerialDataSourceRT.serialEvent:252) - Buffer after read: 534f3234312e
DEBUG 2014-08-11 13:24:58,223 (com.infiniteautomation.io.serial.JsscSerialPortInputStream.serialEvent:119) - Serial Receive Event fired.
DEBUG 2014-08-11 13:24:58,224 (com.infiniteautomation.io.serial.JsscSerialPortInputStream.serialEvent:128) - Recieved: 31373546524f4d3d3234312e3137350d534f3234312e313735484f50533d320d534f3234312e
DEBUG 2014-08-11 13:24:58,225 (com.infiniteautomation.serial.rt.SerialDataSourceRT.serialEvent:281) - Terminator not found in message yet.
DEBUG 2014-08-11 13:24:58,225 (com.infiniteautomation.io.serial.SerialPortProxyEventTask.run:29) - Running event created at: 1407720298224
DEBUG 2014-08-11 13:24:58,226 (com.infiniteautomation.io.serial.JsscSerialPortInputStream.serialEvent:119) - Serial Receive Event fired.
DEBUG 2014-08-11 13:24:58,226 (com.infiniteautomation.serial.rt.SerialDataSourceRT.serialEvent:252) - Buffer after read: 534f3234312e31373546524f4d3d3234312e3137350d
DEBUG 2014-08-11 13:24:58,227 (com.infiniteautomation.io.serial.JsscSerialPortInputStream.serialEvent:128) - Recieved: 313735525353493d2d3531
DEBUG 2014-08-11 13:24:58,227 (com.infiniteautomation.serial.rt.SerialDataSourceRT.serialEvent:274) - Matching will use UTF8: SO241.175FROM=241.175

Here the buffer starts with 534f3234312e - "SO241."
Data is then read from the serial port 31373546524f4d3d3234312e3137350d534f3234312e313735484f50533d320d534f3234312e
"175FROM=241.175
SO241.175HOPS=2
SO241."

The buffer is now
"SO241.175FROM=241.175
SO241.175HOPS=2
SO241."

Then the debug message "Terminator not found in message yet." however there are 2 '\r' strings sitting in the buffer.

The two strings "SO241.175FROM=241.175\r" and "SO241.175HOPS=2\r" then get extracted from the buffer which should leave "SO241." in the buffer. The rest should follow in the next serial port read.

It would seem like the buffer is filling up faster than the data is being extracted from it.

Matt.

terrypacker

Matt,

I've changed the logging to show the buffer as UTF8 instead of as Hex, this should make life a little easier. I also changed the way the terminators are matched and processed, allowing the processing of multiple messages at once. You were correct in assuming that we were "missing" some of the terminators because of the amount of data coming in on the port so quickly.

Give this version a try and let me know how it goes.

Thanks,
Terry

Attachment: download link

mattonfarm

CheersTerry,
The last module ran for a day without crashing so that's an improvement. Hopefully your last change should fix the issue of terminators being missed.

Thank you for your help,
Matt.

mattonfarm

Hi Terry,
That last Data Source seems to have fixed the crashing.
How do I remove the added debug messages from the logs?
I have removed the line from the log4j configuration file and restarted Mango but the messages keep coming.
I am getting daily logs over 650MB in size.

Cheers,
Matt.