Recent Changes - Search:

edit SideBar

RxTxErrorOpeningLockFile

Summary

Calling gnu.io.CommPortIdentifier.getPortIdentifiers() after opening a port will produce a message about locks:

  testRead() Lock file failed
  RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

What is happening is that the first time we call gnu.io.CommPortIdentifier.getPortIdentifiers(), everything is fine and we lock the first port.

Then, the second time we call gnu.io.CommPortIdentifier.getPortIdentifiers(), the first port is locked.

Basically, this message can be ignored.

A workaround would be to call gnu.io.CommPortIdentifier.getPortIdentifiers() only once.

A better fix would be to have not print the lock message if we are enumerating through the ports because a port could be locked between the time we enumerate the ports and the time we actually try to open the port.

How to Repeat

Under Ubuntu 14.04, running

 $PTII/bin/vergil $PTII/ptolemy/actor/lib/jjs/modules/serial/test/auto/SerialHelloWorld.xml

The error messages appear:

  testRead() Lock file failed
  RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

Does the lock file exist?

Does /var/lock/LCK..ttyUSB0 exist before you run the model? If so then remove it.

Also, it could be that the XCTU process is holding the lock.

Also, it could be that the model is referring to the same port in both actors.

SourceCode

Ptolemy is using nrjavaserial.

To get the sources, use:

  git clone https://github.com/NeuronRobotics/nrjavaserial.git

To find the file:

  cd nrjavaserial
  find . -type f | xargs grep "opening lock file"

The results include:

  ./src/main/c/src/SerialImp.c:                   "RXTX fhs_lock() Error: opening lock file: s.",
  ./src/main/c/src/SerialImp.c:                   "RXTX uucp_lock() Error: opening lock file: s\n",
  ./src/main/c/src/SerialImp.c:                           "RXTX is_device_locked() Error: opening lock file: s\n",

Thus src/main/c/src/SerialImp.c is the file and fhs_lock() is the function.

int fhs_lock( const char *filename, int pid )
{
        /*
         * There is a zoo of lockdir possibilities
         * Its possible to check for stale processes with most of them.
         * for now we will just check for the lockfile on most
         * Problem lockfiles will be dealt with.  Some may not even be in use.
         *
         */

#if defined(__linux__)
        //return 0;
#endif
        int fd,j;
        char lockinfo[12], message[200];
        char file[200], *p;

        j = strlen( filename );
        p = ( char * ) filename + j;
        /*  FIXME  need to handle subdirectories /dev/cua/...
            SCO Unix use lowercase all the time
                        taj
        */

        while( *( p - 1 ) != '/' && j-- != 1 )
        {
#if defined ( __unixware__ )
                *p = tolower( *p );
#endif /* __unixware__ */
                p--;
        }
        sprintf( file, "%s/LCK..%s", LOCKDIR, p );
        if ( check_lock_status( filename ) )
        {
                report_warning( "fhs_lock() lockstatus fail\n" );
                return 1;
        }
        fd = open( file, O_CREAT | O_WRONLY | O_EXCL, 0666 );
        if( fd < 0 )
        {
                sprintf( message,
                        "RXTX fhs_lock() Error: opening lock file: %s: %s.",
                        file, strerror(errno) );
                report_error( message );
                fd = open( file,  O_WRONLY );
                if( fd < 0 ){
                        sprintf( message,
                                " FAILED TO OPEN: %s\n",
                                 strerror(errno) );
                        report_error( message );
                        return 1;
                }

                if(check_lock_pid( file, pid )==0){
                        report_error(" It is mine\n" );
                }
                report_error( "\n" );
                close( fd );
                return 1;
        }

        sprintf( lockinfo, "%10d\n",(int) getpid() );
        sprintf( message, "fhs_lock: creating lockfile: %s\n", lockinfo );
        report( message );
        if( ( write( fd, lockinfo, 11 ) ) < 0 )
        {
                sprintf( message,
                                "RXTX fhs_lock() Error: writing lock file: %s: %s\n",
                                file, strerror(errno) );
                report_error( message );
                close( fd );
                return 1;
        }
        close( fd );
        return 0;
}

Building nrjavaserial

See , but basically:

  cd ~/src
  git clone https://github.com/NeuronRobotics/nrjavaserial.git
  sudo add-apt-repository ppa:cwchien/gradle
  sudo apt-get update
  sudo apt-get install gradle
  cd nrjavaserial
  make linux64
  cp ./build/libs/nrjavaserial-3.11.0.jar $PTII/lib/nrjavaserial-3.11.0.devel.jar

Debugging

  1. Edit nrjavaserial/src/main/c/src/SerialImp.c and, at the top, add
    #define DEBUG 1
  2. Recompile:
      make linux64
  3. Update ptII:
      cp ./build/libs/nrjavaserial-3.11.0.jar $PTII/lib/nrjavaserial-3.11.0.7Dec2015.jar
  4. Rerun the model
     $PTII/bin/vergil $PTII/ptolemy/actor/lib/jjs/modules/serial/test/auto/SerialHelloWorld.xml
  5. The following appears:
    fhs_unlock: Removing LockFile
    fhs_lock: creating lockfile:      19418

    open: fd returned is 513
    init_threads: get eis
    init_threads: set eis
    init_threads:  stop
    fhs_lock: creating lockfile:      19418

    fhs_unlock: Removing LockFile
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    P\333^P\370e^? testRead() Lock file failed
    fhs_lock: creating lockfile:      19418

    fhs_unlock: Removing LockFile
    fhs_lock: creating lockfile:      19418

The above looks like a locking problem.

Analysis

Searching using the error message comes up with:

I tried

 export JAVAFLAGS=-Dgnu.io.rxtx.SerialPorts=/dev/ttyUSB1:/dev/ttyUSB0

but that did not help.

Use XCTU

As an experiment, I first used the XBeeJava Example to verify that the XBee Java example would write data to one XBee and then use XCTU to read from another XBee.

Then, I exited XCTU, started the model, removed the reader portion of the model and ran it.

The data did not appear in XCTU, indicating that the writer portion (which is like the XBeeHello example), does not work.

I then did the reverse, where I removed the writer portion of the model and ran the XBeeHello example. The data did not appear.

So, it seems like the SerialHello.xml example is not the same as the XCTU/XBeeHello example.

This is probably because the XBee devices are in AP mode when I use XCTU and XBeeHello.

Revised Test

As per the above,

  $PTII/bin/vergil $PTII/ptolemy/actor/lib/jjs/modules/serial/test/auto/SerialHelloWorld.xml

does not work. However,

  $PTII/bin/vergil $PTII/org/terraswarm/accessor/demo/XBeeHelloWorld/XBeeHelloWorld.xml 

does work.

The problem is that the second time, it fails.

To replicate:

  1. Run $PTII/bin/vergil $PTII/org/terraswarm/accessor/demo/XBeeHelloWorld/XBeeHelloWorld.xml
  2. Run the model for a few iterations.
  3. Hit the stop button
  4. Hit the start button
  5. The following exception appears:
    va.lang.RuntimeException: com.digi.xbee.api.exceptions.InvalidInterfaceException: No such port: /dev/ttyUSB0
            at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:397)
            at jdk.nashorn.api.scripting.ScriptObjectMirror.callMember(ScriptObjectMirror.java:199)
            at jdk.nashorn.api.scripting.NashornScriptEngine.invokeImpl(NashornScriptEngine.java:383)
            at jdk.nashorn.api.scripting.NashornScriptEngine.invokeMethod(NashornScriptEngine.java:199)
            at ptolemy.actor.lib.jjs.JavaScript._invokeMethodInContext(JavaScript.java:1823)
            at ptolemy.actor.lib.jjs.JavaScript.initialize(JavaScript.java:1071)
            at ptolemy.actor.Director.initialize(Director.java:939)
            at ptolemy.actor.Director.initialize(Director.java:908)
            at ptolemy.domains.de.kernel.DEDirector.initialize(DEDirector.java:944)
            at ptolemy.actor.CompositeActor.initialize(CompositeActor.java:929)
            at ptolemy.actor.Manager.initialize(Manager.java:715)
            at ptolemy.actor.Manager.execute(Manager.java:354)
            at ptolemy.actor.Manager.run(Manager.java:1252)
            at ptolemy.actor.Manager$PtolemyRunThread.run(Manager.java:1903)
    Caused by: com.digi.xbee.api.exceptions.InvalidInterfaceException: No such port: /dev/ttyUSB0
            at com.digi.xbee.api.connection.serial.SerialPortRxTx.open(SerialPortRxTx.java:163)
            at com.digi.xbee.api.XBeeDevice.open(XBeeDevice.java:195)
            at ptolemy.actor.lib.jjs.modules.xbee.XBeeHelper.<init>(XBeeHelper.java:88)
            at jdk.nashorn.internal.scripts.Script$Recompilation$1054$4052AA$require.L:1$XBee(/home/sbuser/src/ptII/ptolemy/actor/lib/jjs/external/require.js#209:24<eval>:113)
            at jdk.nashorn.internal.scripts.Script$Recompilation$1050$5396$\^eval\_.initialize(<eval>:135)
            at jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:640)
            at jdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:228)
            at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:393)
            ... 13 more
    Caused by: gnu.io.NoSuchPortException
            at gnu.io.CommPortIdentifier.getPortIdentifier(CommPortIdentifier.java:273)
            at com.digi.xbee.api.connection.serial.SerialPortRxTx.open(SerialPortRxTx.java:161)
            ... 20 more
  6. On standard out:
    sbuser@swarmnuc001:~/src/ptII$ $PTII/bin/vergil org/terraswarm/accessor/demo/XBeeHelloWorld/XBeeHel\
    loWorld.xml
    Updating local copy of the accessors repository.
    In "/home/sbuser/src/ptII/org/terraswarm/accessor/accessors", about to execute:
        svn update --non-interactive --trust-server-cert --accept postpone
    Updating '.':
    At revision 368.
    All Done
    Updated accessor repository.
    JSAccessor: urlSpec is http://terraswarm.org/accessors/net/XBeeIcon.xml, but /home/sbuser/src/ptII/\
    org/terraswarm/accessor/accessors/web/net/XBeeIcon.xml exists, so the latter is being read.
    JSAccessor: urlSpec is http://terraswarm.org/accessors/net/XBeeIcon.xml, but /home/sbuser/src/ptII/\
    org/terraswarm/accessor/accessors/web/net/XBeeIcon.xml exists, so the latter is being read.
    RXTX Warning:  Removing stale lock file. /var/lock/LCK..ttyUSB1
    RXTX Warning:  Removing stale lock file. /var/lock/LCK..ttyUSB0
    1782 ms. Memory: 189440K Free: 89984K (48%)
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    0^T'dO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    \240d(dO^? testRead() Lock file failed
    7438 ms. Memory: 216064K Free: 107183K (50%)
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB1: File exists. It is mine

    @\267
    dO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    @\267
    dO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB1: File exists. It is mine

    ^P\341^QdO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    ^P\341^QdO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB1: File exists. It is mine

    \240L^RdO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    \240L^RdO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB1: File exists. It is mine

    \220\204^RdO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    \220\204^RdO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB1: File exists. It is mine

    \220\230^DdO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    \220\230^DdO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB1: File exists. It is mine

    \260\366)dO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    \260\366)dO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB1: File exists. It is mine

    \220^C*dO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    \220^C*dO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB1: File exists. It is mine

    \200\344*dO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    \200\344*dO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB1: File exists. It is mine

    \320.+dO^? testRead() Lock file failed
    RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyUSB0: File exists. It is mine

    \320.+dO^? testRead() Lock file failed
    1121 ms. Memory: 245248K Free: 105393K (43%)
"15) where sprintf is being used, ensure that the existing ptr refers to

an empty string (uses memset to sizeof)"

Instead of

                (*env)->ReleaseStringUTFChars(env, tty_name, name);
                report_error(name);
                report_error( " testRead() Lock file failed\n" );

do:

                memset(&message[0], 0, sizeof(message));
                sprintf(message, "%s testRead() Lock file failed!\n", name );
                (*env)->ReleaseStringUTFChars(env, tty_name, name);
                report_error(message);

It is probably more that we have the call to ReleaseStringUTFChars() after the use of name than the memset here

One thing that is interesting is that when we start, we sometimes see:

RXTX Warning:  Removing stale lock file. /var/lock/LCK..ttyUSB1
RXTX Warning:  Removing stale lock file. /var/lock/LCK..ttyUSB0

However, we don't see that the second time, when it fails.

The above lines occur in is_device_locked() when the lock files are present, but the pid inside them is not the same as our current pid.

/*----------------------------------------------------------  
 is_device_locked  

   accept:      char * filename.  The device in question including the path.  
   perform:     see if one of the many possible lock files is aready there  
                if there is a stale lock, remove it.  
   return:      1 if the device is locked or somethings wrong.
                0 if its possible to create our own lock file.
   exceptions:  none
   comments:    check if the device is already locked
----------------------------------------------------------*/

int is_device_locked( const char *port_filename )
{
...
                if( kill( (pid_t) pid, 0 ) && errno==ESRCH )
                {
                        sprintf( message,
                                "RXTX Warning:  Removing stale lock file. %s\n",
                                file );
                        report_warning( message );
                        if( unlink( file ) != 0 )
                        {
                                snprintf( message, 80, "RXTX Error:  Unable to \
                                       remove stale lock file: %s\n"
,
                                        file
                                );
                                report_warning( message );
                                return 1;
                        }
                }
 

This suggests that during the second time, we already have the lock.

Replication using a small test case


import gnu.io.CommPort;
import gnu.io.CommPortIdentifier;

import java.util.Enumeration;

public class SerialPortLockTest {

    /**                                                                                                                                  
     * Test for a locking problem  
     * <p>Usage:</p>
     * <pre>
     * javac -classpath .:lib/nrjavaserial-3.11.0.devel.jar SerialPortLockTest.java
     * java -classpath .:lib/nrjavaserial-3.11.0.devel.jar SerialPortLockTest    
     * </pre>                                        
     */

    public static void main(String [] args) {
        try {
            System.out.println("Opening Port 1");
            CommPort port1 = SerialPortLockTest.openPort();
            System.out.println("Port 1: " + port1);
            System.out.println("Opening Port 2");
            CommPort port2 = SerialPortLockTest.openPort();
            System.out.println("Port 2: " + port2);
            System.out.println("Closing port1: ");
            port1.close();
            System.out.println("Closing port2: ");
            port2.close();
            System.out.println("Done.");
        } catch (Throwable throwable) {
            throwable.printStackTrace();
        }
    }

    /** Open the first non-Bluetooth and non-cu Serial port.
     *  @return the port that was opened            
     *  @exception Throwable If looking up a port failed.    
     */

    public static CommPort openPort() throws Throwable {
        System.out.println("Calling gnu.io.CommPortIdentifier.getPortIdentifiers()");
        Enumeration ports = CommPortIdentifier.getPortIdentifiers();
        System.out.println("Done calling gnu.io.CommPortIdentifier.getPortIdentifiers()");
        while (ports.hasMoreElements()) {
            CommPortIdentifier identifier = (CommPortIdentifier) ports
                .nextElement();
            if (identifier.getName().indexOf("/dev/cu.") != -1
                || identifier.getName().indexOf("Bluetooth") != -1) {
                System.out.println("Skipping " + identifier.getName());
            } else {
                CommPortIdentifier portID = CommPortIdentifier.getPortIdentifier(identifier.getName());
                CommPort port = portID.open("SerialPortLockTest", 1000 /* timeout for opening */);
                return port;
            }
        }
        throw new RuntimeException("Could not find any non-Bluetooth, non tty serial ports.");
    }
}
[cxh@terra ptII]$ javac -classpath .:lib/nrjavaserial-3.11.0.devel.jar SerialPortLockTest.java
[cxh@terra ptII]$ java -classpath .:lib/nrjavaserial-3.11.0.devel.jar SerialPortLockTest
Opening Port 1
Calling gnu.io.CommPortIdentifier.getPortIdentifiers()
Done calling gnu.io.CommPortIdentifier.getPortIdentifiers()
Port 1: /dev/ttyS0
Opening Port 2
Calling gnu.io.CommPortIdentifier.getPortIdentifiers()
RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS0: File exists. It is mine

 \234^\\244^R^? testRead() Lock file failed
Done calling gnu.io.CommPortIdentifier.getPortIdentifiers()
Port 2: /dev/ttyS1
Closing port1:
Closing port2:
Done.
[cxh@terra ptII]$

Analysis

In the above run, we get port 1 (/dev/ttyS0) and then call gnu.io.CommPortIdentifier.getPortIdentifiers(), which triggers:

RXTX fhs_lock() Error: opening lock file: /var/lock/LCK..ttyS0: File exists. It is mine

 \234^\\244^R^? testRead() Lock file failed

This happens because

gnu.io.CommPortIdentifier.getPortIdentifiers() calls

RXTXCommDriver.initialize();, which calls

RXTXCommDriver.registerSpecifiedPorts(), which calls

RXTXCommDriver.addSpecifiedPorts(), which calls

RXTXCommDriver.testRead(), which is a native method that checks for several things, including if the lock is present.

What is happening is that the first time we call gnu.io.CommPortIdentifier.getPortIdentifiers(), everything is fine and we lock the first port.

Then, the second time we call gnu.io.CommPortIdentifier.getPortIdentifiers(), the first port is locked.

Basically, this message can be ignored.

A workaround would be to call gnu.io.CommPortIdentifier.getPortIdentifiers() only once.

A better fix would be to have not print the lock message if we are enumerating through the ports because a port could be locked between the time we enumerate the ports and the time we actually try to open the port.

See Also

Edit - History - Print - Recent Changes - Search
Page last modified on December 28, 2015, at 02:06 PM