SerialDataEventListener stops receiving serial data

[menazord]

Hi again!

I've found an issue with SerialDataEventListener... somehow, after 300+ iterations, the listener no longer receives data from serial port, even when serial connection was successfully established

This is my SerialDataEventListener

public class ArduinoDataListener implements SerialDataEventListener {

    private Logger LOGGER = LoggerFactory.getLogger(ArduinoDataListener.class);

    private Double temperature;

    private Long memory;

    @Override
    public void dataReceived(SerialDataEvent event) {

        String payload;

        try{
            payload = event.getAsciiString();
            LOGGER.debug("Payload received : " + payload);

            if (payload.startsWith(DeviceDataType.TEMPERATURE.getIdentifier())){
                payload = payload.replaceAll(DeviceDataType.TEMPERATURE.getIdentifier(), "");
                setTemperature(Double.parseDouble(payload));

            }else if (payload.startsWith(DeviceDataType.FREE_MEMORY.getIdentifier())){
                payload = payload.replaceAll(DeviceDataType.FREE_MEMORY.getIdentifier(), "");
                setMemory(Long.parseLong(payload));
            }

        }catch (IOException ioe){
            LOGGER.error("Error while processing serial payload", ioe);
        }
    }

    public Double getTemperature() {
        return temperature;
    }

    public void setTemperature(Double temperature) {
        this.temperature = temperature;
    }

    public Long getMemory() {
        return memory;
    }

    public void setMemory(Long memory) {
        this.memory = memory;
    }
}

And this is my service code (runs every X minutes via scheduling)

`

@Component("RaspberryPi")
public class RaspberryPi implements Device {

    private Logger LOGGER = LoggerFactory.getLogger(RaspberryPi.class);

    private static final Serial serial = SerialFactory.createInstance();

    private ArduinoDataListener arduinoDataListener;

    @Value("${serial.port}")
    private String serialPort;

    @Value("${serial.baudRate}")
    private Integer baudRate;

    @PostConstruct
    public void configure(){

        LOGGER.info("Configuring listener");
        arduinoDataListener = new ArduinoDataListener();
        serial.addListener(arduinoDataListener);

    }

    @Override
    public DeviceData readData() throws DeviceException{

        try{
            DeviceData data = new DeviceData();

            if (serialPort == null || "".equals(serialPort))
                serialPort = Serial.DEFAULT_COM_PORT;

            LOGGER.info("Attempting connection to " + serialPort + " , baud rate " + baudRate);

            serial.open(serialPort, baudRate);

            if (serial.isOpen()){
                LOGGER.info("Connected");
                // send request, get data

                LOGGER.info("Querying sensor data..");

                LOGGER.debug("Probing");
                serial.write(DeviceDataType.DUMMY.getCommand());
                Thread.sleep(3000);

                // Request temperature
                LOGGER.debug("Requesting TEMPERATURE");
                serial.write(DeviceDataType.TEMPERATURE.getCommand());
                Thread.sleep(3000);

                LOGGER.info("Sensor data retrieved");

                data.setTemperature(arduinoDataListener.getTemperature());

                LOGGER.debug("Arduino memory status : " + arduinoDataListener.getMemory() + " free");

            }
            return data;

        } catch (IOException e) {
            throw new DeviceException("Error while connecting to device.", e);
        } catch (Exception e) {
            throw new DeviceException("Unexpected error while connecting to device.", e);
        } finally {
            LOGGER.info("Closing serial connection");
            if (!serial.isClosed()){
                try{
                    serial.close();
                }catch (IOException ioe){
                    LOGGER.error("Could not close Serial connection gracefully, continuing", ioe);
                }
            }
        }
    }
}

I only configure DataListener once, and reuse it on every iteration.

The thing is, after 300 iterations or more, DataListener no longer is triggered

This is the log for my first iteration

2017-09-10 21:47:00.010  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.GardenwatchApplication   : Device RaspberryB sensing status for garden Piranha80
2017-09-10 21:47:00.021  INFO 1024 --- [pool-3-thread-1] c.f.g.s.sensing.SensingServiceImpl       : Starting sense cycle
2017-09-10 21:47:00.034  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Attempting connection to /dev/ttyACM0 , baud rate 9600
2017-09-10 21:47:00.790  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Connected
2017-09-10 21:47:00.799  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Querying sensor data..
2017-09-10 21:47:00.808 DEBUG 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Probing
2017-09-10 21:47:03.874 DEBUG 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Requesting TEMPERATURE
2017-09-10 21:47:04.148 DEBUG 1024 --- [ngle-executor-0] c.f.g.d.listener.ArduinoDataListener     : Payload received : TEMP17.18
2017-09-10 21:47:09.909 DEBUG 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Requesting FREE MEMORY
2017-09-10 21:47:09.980 DEBUG 1024 --- [ngle-executor-0] c.f.g.d.listener.ArduinoDataListener     : Payload received : FMEM1587
2017-09-10 21:47:11.423  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Sensor data retrieved
2017-09-10 21:47:11.435 DEBUG 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Arduino memory status : 1587 free
2017-09-10 21:47:11.453  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Closing serial connection
2017-09-10 21:47:15.955  INFO 1024 --- [pool-3-thread-1] o.h.h.i.QueryTranslatorFactoryInitiator  : HHH000397: Using ASTQueryTranslatorFactory
2017-09-10 21:47:37.310  INFO 1024 --- [pool-3-thread-1] c.f.g.s.sensing.SensingServiceImpl       : Sensor data has been saved (id : 2301)
2017-09-10 21:47:37.329  INFO 1024 --- [pool-3-thread-1] c.f.g.s.sensing.SensingServiceImpl       : Sense cycle completed
2017-09-10 21:47:37.349  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.GardenwatchApplication   : ========= STATUS ===========
2017-09-10 21:47:37.360  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.GardenwatchApplication   :  Temperature   : 17.18 ºC
2017-09-10 21:47:37.419  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.GardenwatchApplication   : ============================
2017-09-10 21:47:37.430  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.GardenwatchApplication   : Sensing completed.

And this is my output for iteration 345

2017-09-11 03:31:00.001  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.GardenwatchApplication   : Device RaspberryB sensing status for garden Piranha80
2017-09-11 03:31:00.513  INFO 1024 --- [pool-3-thread-1] c.f.g.s.sensing.SensingServiceImpl       : Starting sense cycle
2017-09-11 03:31:00.520  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Attempting connection to /dev/ttyACM0 , baud rate 9600
2017-09-11 03:31:00.581  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Connected
2017-09-11 03:31:00.587  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Querying sensor data..
2017-09-11 03:31:00.592 DEBUG 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Probing
2017-09-11 03:31:03.599 DEBUG 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Requesting TEMPERATURE
2017-09-11 03:31:09.613 DEBUG 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Requesting FREE MEMORY
2017-09-11 03:31:11.119  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Sensor data retrieved
2017-09-11 03:31:11.122 DEBUG 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Arduino memory status : 1587 free
2017-09-11 03:31:11.131  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.device.pi.RaspberryPi    : Closing serial connection
2017-09-11 03:31:11.760  INFO 1024 --- [pool-3-thread-1] c.f.g.s.sensing.SensingServiceImpl       : Sensor data has been saved (id : 2645)
2017-09-11 03:31:11.768  INFO 1024 --- [pool-3-thread-1] c.f.g.s.sensing.SensingServiceImpl       : Sense cycle completed
2017-09-11 03:31:11.774  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.GardenwatchApplication   : ========= STATUS ===========
2017-09-11 03:31:11.780  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.GardenwatchApplication   :  Temperature   : 12.37 ºC
2017-09-11 03:31:11.799  INFO 1024 --- [pool-3-thread-1] c.f.gardenwatch.GardenwatchApplication   : ============================

Note that logging for "Payload received" no longer appears, and values for memory and temperature are the same as the last time they printed correctly (as values from listener do not reset)

Can you guide me to check if my code is using API correctly?

[menazord]

Also seems related to thread "pi4j-single-executor-0"

[menazord]

Hi

Executed another run last night, and data listener stopped working on iteration 355 .

It seems to always fail on this iteration, could this be a memory issue ? I get no errors on logs, it just stops working

Running time was almost 6 hours

On each sensing cycle I send 4 messages to Arduino and expect 4 responses. This means on each cycle, threadPoolExecutor executes 4 tasks

This is the current status of ThreadPoolExecutor

I have remote debugging enabled on my running app, and "completed tasks" does not increment. 1376 tasks / 4 tasks per cycle = 344 cycles, just as before.

Thread "pi4j-single-executor-0" still appears on Threads window, as WAIT

[menazord]

Hi @savageautomate

After testing several combinations and code enhancements, keeping the serial connection open during all program execution seems to solve the problem

I've achieved more than 3.000 iterations without any problems, and data is arriving consistently from remote serial devices.

[savageautomate]

@menazord

Thank you for your detailed thread and for narrowing down the problematic area to opening and closing the serial connection. I'll have to have a look to see what all is going on under the covers during a serial closure.