MINA
  1. MINA
  2. DIRMINA-720

Hardware Flow Control Disables Serial Port on Windows Platform

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0.0-M4, 2.0.0-M5, 2.0.0-M6, 2.0.0-RC1
    • Fix Version/s: 2.0.0
    • Component/s: Transport
    • Labels:
      None
    • Environment:
      Windows, serial connections only
      Specifically does NOT happen on Linux systems (others untested)

      Description

      Attempting protocol discovery on single port – Most protocols use no flow control, one using RTS/CTS. Each protocol attempts connection, fails (because far end device turned off), then tries next protocol.

      Test involves letting discovery fail through multiple cycles (ie test all available protocols) then eventually turn on device and see it get discovered when it's protocol cycles back around.

      HOWEVER... test failed before first cycle completed, because first protocol using CTS/RTS flow control (via FlowControl.RTSCTS_OUT parameter to SerialAddress constructor) is the last one to successfully open the serial port.

      While the protocol with RTS/CTS works (in that it properly fails), the next, and all following, protocols fail immediately as the port throws a PortInUseException on open attempt.

      Changing FlowControl.RTSCTS_OUT to FlowControl.NONE makes this test run fine. It also, however, breaks that particular protocol because the far end device expects flow control that it does not see.

        Activity

        Hide
        Julien Vermillard added a comment -

        you tried to .close the session after the sucessfull opening ? if no, it's normaly you got a port in use execption

        Show
        Julien Vermillard added a comment - you tried to .close the session after the sucessfull opening ? if no, it's normaly you got a port in use execption
        Hide
        boB Gage added a comment - - edited

        Yes, for each discovery attempt I open the session, (usually) send a request, (always) wait to see some data, try to parse it.

        If either no data appears (timeout) or data appears that I cannot parse, I close the port, sleep a couple seconds and repeat the process with the next protocol.

        The protocol list is circular. Eventually (given the nothing's out there scenario) each port times out for each protocol and tries them all again and again. One of our "smoke tests" is to stay in this state for awhile and then turn on external devices and see them get discovered.

        The first time a protocol using hardware flow control is attempted, it operates normally (ie displays no errors other than time out). BUT the next protocol attempt (and every one thereafter) fails with the PortInUseException.

        This MIGHT mean that the hardware flow controlled protocol's close() method failed; causing the subsequent exceptions.


        Oh, almost forgot to add!

        I have changed the order of the protocols around and turned on & off the hardware flow control to confirm that it all works fine with no flow control anywhere and breaks after the first protocol requiring hardware flow control.

        Show
        boB Gage added a comment - - edited Yes, for each discovery attempt I open the session, (usually) send a request, (always) wait to see some data, try to parse it. If either no data appears (timeout) or data appears that I cannot parse, I close the port, sleep a couple seconds and repeat the process with the next protocol. The protocol list is circular. Eventually (given the nothing's out there scenario) each port times out for each protocol and tries them all again and again. One of our "smoke tests" is to stay in this state for awhile and then turn on external devices and see them get discovered. The first time a protocol using hardware flow control is attempted, it operates normally (ie displays no errors other than time out). BUT the next protocol attempt (and every one thereafter) fails with the PortInUseException. This MIGHT mean that the hardware flow controlled protocol's close() method failed; causing the subsequent exceptions. — Oh, almost forgot to add! I have changed the order of the protocols around and turned on & off the hardware flow control to confirm that it all works fine with no flow control anywhere and breaks after the first protocol requiring hardware flow control.
        Hide
        Julien Vermillard added a comment -

        The port opening failure with RTSCTS_OUT is not happening on my Linux computer

        Can you create me a test case, or try to extract the rxtx error/exception in SerialSessionImpl.java open method ?
        Trying to put MINA logs in DEBUG level can worth a try too.

        Show
        Julien Vermillard added a comment - The port opening failure with RTSCTS_OUT is not happening on my Linux computer Can you create me a test case, or try to extract the rxtx error/exception in SerialSessionImpl.java open method ? Trying to put MINA logs in DEBUG level can worth a try too.
        Hide
        boB Gage added a comment -

        Retested with DIRMINA-740 fixes. Unfortunately no change was detected.

        Once a given COM port has been opened with hardware flow control, all future attempts to open it fail with a PortInUseException.

        This behaviour is ONLY seen on Windows [ XP?] systems – same tests on Linux systems work as expected.

        From our application log (whitespace added for legibility):

        2009-10-13 11:43:37,156 [PM.1_COM5] INFO MonitorSupport - Opening session to port [COM5] from [WelchAllyn]
        ^^^^^ Matches our ConnectFuture cf = ioc.connect(address) call

        2009-10-13 11:43:42,421 [PM.1_COM5] INFO MonitorSupport - Not connected after 5 seconds. Canceling connect.
        ^^^^^ After cf.await() times out, cf.isConnected() returned false

        2009-10-13 11:43:42,421 [PM.1_COM5] ERROR MonitorSupport - Exception [PortInUseException] on open.
        cf.getException().getClass().getSimpleName() ^^^^^^^^^^^^^^^^^^^^^^

        vvvvvvv This is cf.getException()'s stack trace
        gnu.io.PortInUseException: Apache MINA
        at gnu.io.CommPortIdentifier.open(CommPortIdentifier.java:452)
        at org.apache.mina.transport.serial.SerialConnector.initializePort(SerialConnector.java:155)
        at org.apache.mina.transport.serial.SerialConnector.connect0(SerialConnector.java:94)
        at org.apache.mina.core.service.AbstractIoConnector.connect(AbstractIoConnector.java:262)
        at org.apache.mina.core.service.AbstractIoConnector.connect(AbstractIoConnector.java:172)
        at com.merge.frontiers.physio.monitors.MonitorSupport.open(MonitorSupport.java:330)
        at com.merge.frontiers.physio.monitors.MonitorSupport.open(MonitorSupport.java:453)
        at com.merge.frontiers.physio.framework.PortManager.establishConnection(PortManager.java:416)
        at com.merge.frontiers.physio.framework.PortManager.tryOne(PortManager.java:351)
        at com.merge.frontiers.physio.framework.PortManager.run(PortManager.java:244)

        Show
        boB Gage added a comment - Retested with DIRMINA-740 fixes. Unfortunately no change was detected. Once a given COM port has been opened with hardware flow control, all future attempts to open it fail with a PortInUseException. This behaviour is ONLY seen on Windows [ XP?] systems – same tests on Linux systems work as expected. From our application log (whitespace added for legibility): 2009-10-13 11:43:37,156 [PM.1_COM5] INFO MonitorSupport - Opening session to port [COM5] from [WelchAllyn] ^^^^^ Matches our ConnectFuture cf = ioc.connect(address) call 2009-10-13 11:43:42,421 [PM.1_COM5] INFO MonitorSupport - Not connected after 5 seconds. Canceling connect. ^^^^^ After cf.await() times out, cf.isConnected() returned false 2009-10-13 11:43:42,421 [PM.1_COM5] ERROR MonitorSupport - Exception [PortInUseException] on open. cf.getException().getClass().getSimpleName() ^^^^^^^^^^^^^^^^^^^^^^ vvvvvvv This is cf.getException()'s stack trace gnu.io.PortInUseException: Apache MINA at gnu.io.CommPortIdentifier.open(CommPortIdentifier.java:452) at org.apache.mina.transport.serial.SerialConnector.initializePort(SerialConnector.java:155) at org.apache.mina.transport.serial.SerialConnector.connect0(SerialConnector.java:94) at org.apache.mina.core.service.AbstractIoConnector.connect(AbstractIoConnector.java:262) at org.apache.mina.core.service.AbstractIoConnector.connect(AbstractIoConnector.java:172) at com.merge.frontiers.physio.monitors.MonitorSupport.open(MonitorSupport.java:330) at com.merge.frontiers.physio.monitors.MonitorSupport.open(MonitorSupport.java:453) at com.merge.frontiers.physio.framework.PortManager.establishConnection(PortManager.java:416) at com.merge.frontiers.physio.framework.PortManager.tryOne(PortManager.java:351) at com.merge.frontiers.physio.framework.PortManager.run(PortManager.java:244)
        Hide
        Julien Vermillard added a comment -

        Look like it's a RXTX problem. You should try to write a minimal RXTX program, open the port with HW flow control.

        Show
        Julien Vermillard added a comment - Look like it's a RXTX problem. You should try to write a minimal RXTX program, open the port with HW flow control.
        Hide
        boB Gage added a comment -

        I added this test into our code – prior to the first port discovery attempt:

        try

        { logger.info("HFCtest -- Opening port via RXTX w/ Datex parameters"); CommPortIdentifier portId = CommPortIdentifier.getPortIdentifier(address.getName()); SerialPort serialPort = (SerialPort) portId.open("Demo application", 5000); serialPort.setSerialPortParams(19200, SerialPort.DATABITS_8, SerialPort.STOPBITS_1, SerialPort.PARITY_EVEN); logger.info(" Setting hardware flow control"); serialPort.setFlowControlMode(SerialPort.FLOWCONTROL_RTSCTS_IN+SerialPort.FLOWCONTROL_RTSCTS_OUT); logger.info(" Port is open. Holding 5 seconds"); Thread.sleep(5000); logger.info(" Closing port and continuing"); serialPort.close(); }

        catch (NoSuchPortException e)

        { logger.error("getPortIdentifier failure", e); }

        catch (PortInUseException e)

        { logger.error("open failure", e); }

        catch (UnsupportedCommOperationException e)

        { logger.error("setSerialPortParams() or setFlowControlMode() failure", e); }

        catch (InterruptedException e)

        { logger.error("Sleep interrupted", e); }

        My logs show the port being opened, hardware flow control being set, the 5-second pause, and the port being closed again. None of the catch clauses above is executed.

        Discovery then proceeds normally with Flow control NONE devices and everything works fine.

        Add in even one Hardware flow control (RTSCTS_IN_OUT) and the port is flagged "in use" on all subsequent attempts.

        I have switched device drivers around – took a previously proven non-flow controlled device driver and set it to use hardware flow control – the results are exactly the same.

        Once Mina opens a Windows serial port with hardware flow control, the port cannot be re-used until the program is exited and restarted.

        Show
        boB Gage added a comment - I added this test into our code – prior to the first port discovery attempt: try { logger.info("HFCtest -- Opening port via RXTX w/ Datex parameters"); CommPortIdentifier portId = CommPortIdentifier.getPortIdentifier(address.getName()); SerialPort serialPort = (SerialPort) portId.open("Demo application", 5000); serialPort.setSerialPortParams(19200, SerialPort.DATABITS_8, SerialPort.STOPBITS_1, SerialPort.PARITY_EVEN); logger.info(" Setting hardware flow control"); serialPort.setFlowControlMode(SerialPort.FLOWCONTROL_RTSCTS_IN+SerialPort.FLOWCONTROL_RTSCTS_OUT); logger.info(" Port is open. Holding 5 seconds"); Thread.sleep(5000); logger.info(" Closing port and continuing"); serialPort.close(); } catch (NoSuchPortException e) { logger.error("getPortIdentifier failure", e); } catch (PortInUseException e) { logger.error("open failure", e); } catch (UnsupportedCommOperationException e) { logger.error("setSerialPortParams() or setFlowControlMode() failure", e); } catch (InterruptedException e) { logger.error("Sleep interrupted", e); } My logs show the port being opened, hardware flow control being set, the 5-second pause, and the port being closed again. None of the catch clauses above is executed. Discovery then proceeds normally with Flow control NONE devices and everything works fine. Add in even one Hardware flow control (RTSCTS_IN_OUT) and the port is flagged "in use" on all subsequent attempts. I have switched device drivers around – took a previously proven non-flow controlled device driver and set it to use hardware flow control – the results are exactly the same. Once Mina opens a Windows serial port with hardware flow control, the port cannot be re-used until the program is exited and restarted.
        Hide
        boB Gage added a comment -

        Found out a little bit more today ...

        The problem does appear to be happening in the session.close process. And it's apparently two-fold, with issues both in our code and in the Mina layer.

        First our code, which I'm looking at ways to fix, has several threads making things happen and shortly after one invalidates the connection and closes the port, a different thread attempts discovery on the next device which re-opens the port.

        The second thread is not synchronized with the first and is attempting to open the port before the CloseFuture from session.close() has completed.

        HOWEVER ... the root problem is that the code:

        Show
        boB Gage added a comment - Found out a little bit more today ... The problem does appear to be happening in the session.close process. And it's apparently two-fold, with issues both in our code and in the Mina layer. First our code, which I'm looking at ways to fix, has several threads making things happen and shortly after one invalidates the connection and closes the port, a different thread attempts discovery on the next device which re-opens the port. The second thread is not synchronized with the first and is attempting to open the port before the CloseFuture from session.close() has completed. HOWEVER ... the root problem is that the code:
        Hide
        boB Gage added a comment - - edited

        Found out a little bit more today ...

        The problem does appear to be happening in the session.close process. And it's apparently two-fold, with issues both in our code and in the Mina layer.

        First our code, which I'm looking at ways to fix, has several threads making things happen and shortly after one invalidates the connection and closes the port, a different thread attempts discovery on the next device which re-opens the port.

        The second thread is not synchronized with the first and is attempting to open the port before the CloseFuture from session.close() has completed.

        HOWEVER ... the root problem is that the code:
        CloseFuture cf = session.close(true); // session is an IoSession
        cf.await(30, TimeUnit.SECONDS);

        Doesn't work. As far as I can tell, because the session.close(true) method has not returned.

        Show
        boB Gage added a comment - - edited Found out a little bit more today ... The problem does appear to be happening in the session.close process. And it's apparently two-fold, with issues both in our code and in the Mina layer. First our code, which I'm looking at ways to fix, has several threads making things happen and shortly after one invalidates the connection and closes the port, a different thread attempts discovery on the next device which re-opens the port. The second thread is not synchronized with the first and is attempting to open the port before the CloseFuture from session.close() has completed. HOWEVER ... the root problem is that the code: CloseFuture cf = session.close(true); // session is an IoSession cf.await(30, TimeUnit.SECONDS); Doesn't work. As far as I can tell, because the session.close(true) method has not returned.
        Hide
        boB Gage added a comment -

        Cleaned up my code and the re-discovery now won't happen until the session.close() has completed.

        Now the heart of the problem is very apparent.... and still only happens on Windows machines with hardware flow control turned on.

        After an IoSession (session) has been opened using hardware flow control ( Said driver sending a one-character command "V" and timing out with no response ), the

        session.close(true)

        call never returns, and the thread making the call is never heard from again. Now no further attempts are made to open the port (just time out & watchdog threads chugging); but when they were, they were getting PortInUseExceptions – now quite predictably.

        I turn off the hardware flow control on the first driver (does not match the device on the port) and restart my program – the first device times out, the second device opens the port, sees data it recognizes, and everything's golden.

        Turn hardware flow control back on for the first device (property file setting) & restart – first device times out, then fails to close. The main thread hangs in session.close(true) and never returns.

        I can go back and forth at will and control the problem with my flow control setting for the non-matching driver (which will always time out).

        I've done the beginnings of a track through session.close(). It could block indefinitely based on synchronized () blocks based on AbstractIoSession.lock [ AbstractIoSession.close() ] or DefaultIoFuture.lock [ DefaultIoFuture.isDone() ] – neither of these blocks is logged, so there's no easy way to tell which we might be blocking on.

        Show
        boB Gage added a comment - Cleaned up my code and the re-discovery now won't happen until the session.close() has completed. Now the heart of the problem is very apparent.... and still only happens on Windows machines with hardware flow control turned on. After an IoSession (session) has been opened using hardware flow control ( Said driver sending a one-character command "V" and timing out with no response ), the session.close(true) call never returns, and the thread making the call is never heard from again. Now no further attempts are made to open the port (just time out & watchdog threads chugging); but when they were, they were getting PortInUseExceptions – now quite predictably. I turn off the hardware flow control on the first driver (does not match the device on the port) and restart my program – the first device times out, the second device opens the port, sees data it recognizes, and everything's golden. Turn hardware flow control back on for the first device (property file setting) & restart – first device times out, then fails to close. The main thread hangs in session.close(true) and never returns. I can go back and forth at will and control the problem with my flow control setting for the non-matching driver (which will always time out). I've done the beginnings of a track through session.close(). It could block indefinitely based on synchronized () blocks based on AbstractIoSession.lock [ AbstractIoSession.close() ] or DefaultIoFuture.lock [ DefaultIoFuture.isDone() ] – neither of these blocks is logged, so there's no easy way to tell which we might be blocking on.
        Hide
        boB Gage added a comment -

        Tracked it further down and it left the Mina library..... RXTX's gnu.io.CommPort.close() is not returning. I'm wondering if flow control is making it wait for some recognition from the far end that it's ready to be closed ( ie assuming there's something out there that isn't )...

        Show
        boB Gage added a comment - Tracked it further down and it left the Mina library..... RXTX's gnu.io.CommPort.close() is not returning. I'm wondering if flow control is making it wait for some recognition from the far end that it's ready to be closed ( ie assuming there's something out there that isn't )...
        Hide
        boB Gage added a comment -

        Woo hoo! A work around!!

        SerialSessionImpl.java

        private class SerialIoProcessor ... {

        ...
        public void remove(SerialSessionImpl session)

        { ... port.close(); ... }

        ...
        }

        The port.close() call is where my code dead locks.

        Adding:
        try

        { // An experiment... Turn flow control off regardless right before close port.setFlowControlMode(SerialPort.FLOWCONTROL_NONE); }

        catch (UnsupportedCommOperationException e)

        { System.out.println("Failed clearing flow control for close! " + e); }

        Directly BEFORE the port.close() call stops the deadlock. Port gets reused by next device whether hardware flow control is turned on or off.

        Any chance of getting something like this into the official code stream ???

        Show
        boB Gage added a comment - Woo hoo! A work around!! SerialSessionImpl.java private class SerialIoProcessor ... { ... public void remove(SerialSessionImpl session) { ... port.close(); ... } ... } The port.close() call is where my code dead locks. Adding: try { // An experiment... Turn flow control off regardless right before close port.setFlowControlMode(SerialPort.FLOWCONTROL_NONE); } catch (UnsupportedCommOperationException e) { System.out.println("Failed clearing flow control for close! " + e); } Directly BEFORE the port.close() call stops the deadlock. Port gets reused by next device whether hardware flow control is turned on or off. Any chance of getting something like this into the official code stream ???
        Hide
        boB Gage added a comment -

        Rats.... I see RC1 is out and does not include anything similar to:

        Index: transport-serial/src/main/java/org/apache/mina/transport/serial/SerialSessionImpl.java
        ===================================================================
        — transport-serial/src/main/java/org/apache/mina/transport/serial/SerialSessionImpl.java (revision 825265)
        +++ transport-serial/src/main/java/org/apache/mina/transport/serial/SerialSessionImpl.java (working copy)
        @@ -22,6 +22,7 @@
        import gnu.io.SerialPort;
        import gnu.io.SerialPortEvent;
        import gnu.io.SerialPortEventListener;
        +import gnu.io.UnsupportedCommOperationException;

        import java.io.IOException;
        import java.io.InputStream;
        @@ -292,6 +293,11 @@
        ExceptionMonitor.getInstance().exceptionCaught(e);
        }

        + try

        { // Turn flow control off right before close to avoid deadlock + port.setFlowControlMode(SerialPort.FLOWCONTROL_NONE); + }

        catch (UnsupportedCommOperationException e)

        { + ExceptionMonitor.getInstance().exceptionCaught(e); + }

        port.close();
        flush(session);
        synchronized (readReadyMonitor) {

        Any hope it'll land in RC2 ?? It does fix a known deadlock.

        Show
        boB Gage added a comment - Rats.... I see RC1 is out and does not include anything similar to: Index: transport-serial/src/main/java/org/apache/mina/transport/serial/SerialSessionImpl.java =================================================================== — transport-serial/src/main/java/org/apache/mina/transport/serial/SerialSessionImpl.java (revision 825265) +++ transport-serial/src/main/java/org/apache/mina/transport/serial/SerialSessionImpl.java (working copy) @@ -22,6 +22,7 @@ import gnu.io.SerialPort; import gnu.io.SerialPortEvent; import gnu.io.SerialPortEventListener; +import gnu.io.UnsupportedCommOperationException; import java.io.IOException; import java.io.InputStream; @@ -292,6 +293,11 @@ ExceptionMonitor.getInstance().exceptionCaught(e); } + try { // Turn flow control off right before close to avoid deadlock + port.setFlowControlMode(SerialPort.FLOWCONTROL_NONE); + } catch (UnsupportedCommOperationException e) { + ExceptionMonitor.getInstance().exceptionCaught(e); + } port.close(); flush(session); synchronized (readReadyMonitor) { Any hope it'll land in RC2 ?? It does fix a known deadlock.
        Hide
        Julien Vermillard added a comment -

        Will be in RC2, thanks for the patch

        Show
        Julien Vermillard added a comment - Will be in RC2, thanks for the patch
        Hide
        boB Gage added a comment -

        Excellent, thanks!!!!

        Show
        boB Gage added a comment - Excellent, thanks!!!!
        Hide
        Julien Vermillard added a comment -

        applied the patch

        Show
        Julien Vermillard added a comment - applied the patch

          People

          • Assignee:
            Julien Vermillard
            Reporter:
            boB Gage
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development