#51 port open fail: gnu.io.PortInUseException

Development version
open
5
2010-02-22
2010-02-22
peter gervai
No

3730 - BT747 2.X.1679 Build:BT747_mdeweerd.1679.20100217105057680
3730 - Initial: 1019x579 Screen: 1280x1024 Final: 1019x579
3730 - Linux
3731 - i386
3731 - 2.6.32-trunk-686
3731 - 1.6.0_17
3731 - Fail com.sun.java.swing.plaf.windows.WindowsLookAndFeel
Fail com.sun.java.swing.plaf.windows.WindowsClassicLookAndFeel
Success com.sun.java.swing.plaf.nimbus.NimbusLookAndFeel
javax.swing.plaf.metal.MetalLookAndFeel
com.sun.java.swing.plaf.nimbus.NimbusLookAndFeel
com.sun.java.swing.plaf.motif.MotifLookAndFeel
com.sun.java.swing.plaf.gtk.GTKLookAndFeel

14769 - Classgps.connection.GPSRxTxPort
Experimental: JNI_OnLoad called.

gnu.io.PortInUseException: grin PID = 10787 Program = java
at gnu.io.CommPortIdentifier.open(CommPortIdentifier.java:354)
at gps.connection.GPSRxTxPort.openPort(Unknown Source)
at gps.connection.GPSrxtx.myOpenPort(Unknown Source)
at gps.connection.GPSrxtx.setFreeTextPortAndOpen(Unknown Source)
at bt747.model.Controller.openFreeTextPort(Unknown Source)
at bt747.j2se_view.BT747Main.access$300(Unknown Source)
at bt747.j2se_view.BT747Main$7.actionPerformed(Unknown Source)
at javax.swing.AbstractButton.fireActionPerformed(AbstractButton.java:1995)
at javax.swing.AbstractButton$Handler.actionPerformed(AbstractButton.java:2318)
at javax.swing.DefaultButtonModel.fireActionPerformed(DefaultButtonModel.java:387)
at javax.swing.DefaultButtonModel.setPressed(DefaultButtonModel.java:242)
at javax.swing.plaf.basic.BasicButtonListener.mouseReleased(BasicButtonListener.java:236)
at java.awt.Component.processMouseEvent(Component.java:6263)
at javax.swing.JComponent.processMouseEvent(JComponent.java:3255)
at java.awt.Component.processEvent(Component.java:6028)
at java.awt.Container.processEvent(Container.java:2041)
at java.awt.Component.dispatchEventImpl(Component.java:4630)
at java.awt.Container.dispatchEventImpl(Container.java:2099)
at java.awt.Component.dispatchEvent(Component.java:4460)
at java.awt.LightweightDispatcher.retargetMouseEvent(Container.java:4574)
at java.awt.LightweightDispatcher.processMouseEvent(Container.java:4238)
at java.awt.LightweightDispatcher.dispatchEvent(Container.java:4168)
at java.awt.Container.dispatchEventImpl(Container.java:2085)
at java.awt.Window.dispatchEventImpl(Window.java:2475)
at java.awt.Component.dispatchEvent(Component.java:4460)
at java.awt.EventQueue.dispatchEvent(EventQueue.java:599)
at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:269)
at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:184)
at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:174)
at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:169)
at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:161)
at java.awt.EventDispatchThread.run(EventDispatchThread.java:122)
18391 - Port opened
93444 - Attempting saving settings to ...

What I believe:
1) the program blocks the port from itself
2) the Experimental: JNI_OnLoad called. line is important, it shows that the port open is bound to fail.

But I believe I can help fixing it. My hack to make it work 100% of the time is:
1) open a fake port, preferably /dev/mdeweerd, connect it, watch JNI_onload activating and connect fail with illegal port
2) set the proper port (in my holux m-1000c case /dev/rfcomm1, wait until SER :/dev/rfcomm1 line appears), then connect
3) no JNI_onload appears
4) port opens just fine:
30301 - SER :/dev/rfcomm1
30302 - Port opened
32987 - Classgps.connection.GPSRxTxPort
37088 - Port opened
37094 - Attempting saving settings to ...

I'm not yet java beginner, so your task is to try to fix, mine is to try to thank you. :-)

Discussion

  • Mario De Weerd
    Mario De Weerd
    2010-02-22

    Hi

    I think JNI_onload has to appear at least once - this indicates that the native code is being loaded.

    How are you starting BT747 (webstart, RXT2.2 pre or other ?=.

    When you get the error message:
    gnu.io.PortInUseException: grin PID = 10787 Program = java .

    This indicates that the port is in use by a process which is a java process. It could be as you suggest that this is the same BT747 java process. To make sure that that is the case, can you please leave the program open where the error is reported and in a shell (or other appropriate means) kill the reported process. In a shell this would be 'kill -9 10787'. The number '10787' is taken from the error message.
    After the kill, if BT747 is still open, try to connect again.
    If BT747 closes, then this confirms that BT747 is opening the port itself and then finds itself blocked by itself.

    Following your precisions, I'll try to identify the potential issue and give you some other stuff to try (or the solution).

     
  • peter gervai
    peter gervai
    2010-02-22

    I'm using run_j2se (that machine isn't usually online).
    I have a better way (actually two) to be sure that the process is indeed itself:
    1) fuser [oh, this is linux, if you didn't realise from the /dev/rfcomm1 already] tells me who uses the device, and it's bt747
    2) /var/run/LCK..rfcomm1 contains bt747's pid.

    (I'm not that avid java user, bt747 is the only one using the beast.)

    So basically I'm sure bt747 got the port, opened it and locked. Then it tries and fails to open it again somehow.

    Unfortunately the machine in question which have bluetooth interface isn't my desktop one, so I cannot just install eclipse and debug it easily. My BT dongle's on the way home. :-) Until then I can run any debug version you prepare if you wish me to (apart from time constraints of real life).

     
  • Mario De Weerd
    Mario De Weerd
    2010-02-22

    Ok, this all is pretty strange,. I do a 'portIdentifier.isCurrentlyOwned()' test which should indicate if the port is in use, but that obviously fails. I found an entry on the web suggesting that that may not work, so I am throwing the test out of my code and relying on the exceptions only (there was not much use of it anyway).

    Maybe that test was in itself messing things up given the slowness of bluetooth. It could be that the test kind of assigns the port to BT747, but it returns false as a test. When I then try to open the port, RXTX says the port is already in use.

    Also activate 'debug' - it will add at least one extra message to the info window.

    I made a new build, adding one extra change that might improve things in some cases.

    FYI: The webstart version is also useable offline. And if you use the 'mapcachee' (by settting an existing directory), you'll even have maps offline (in case you did not know that).

     
  • Mario De Weerd
    Mario De Weerd
    2010-02-22

    You can try BT747_2.X.1683_full.zip (and do activate 'debug' - connection debug is not needed).

     
  • peter gervai
    peter gervai
    2010-02-24

    23207 - BT747 2.X.1684 Build:BT747_mdeweerd.1684.20100223215652629
    23207 - Initial: 1019x579 Screen: 1280x1024 Final: 1019x579
    23208 - Linux
    23208 - i386
    23208 - 2.6.32-trunk-686
    23208 - 1.6.0_17
    23208 - Fail com.sun.java.swing.plaf.windows.WindowsLookAndFeel
    Fail com.sun.java.swing.plaf.windows.WindowsClassicLookAndFeel
    Success com.sun.java.swing.plaf.nimbus.NimbusLookAndFeel
    javax.swing.plaf.metal.MetalLookAndFeel
    com.sun.java.swing.plaf.nimbus.NimbusLookAndFeel
    com.sun.java.swing.plaf.motif.MotifLookAndFeel
    com.sun.java.swing.plaf.gtk.GTKLookAndFeel

    110400 - Classgps.connection.GPSRxTxPort
    Info: trying to open '/dev/rfcomm1'
    Experimental: JNI_OnLoad called.
    Error: Port /dev/rfcomm1is currently in use
    gnu.io.PortInUseException: grin PID = 17000 Program = java
    at gnu.io.CommPortIdentifier.open(CommPortIdentifier.java:354)
    at gps.connection.GPSRxTxPort.openPort(Unknown Source)
    at gps.connection.GPSrxtx.myOpenPort(Unknown Source)
    at gps.connection.GPSrxtx.setFreeTextPortAndOpen(Unknown Source)
    at bt747.model.Controller.openFreeTextPort(Unknown Source)
    at bt747.j2se_view.BT747Main.access$300(Unknown Source)
    at bt747.j2se_view.BT747Main$7.actionPerformed(Unknown Source)
    at javax.swing.AbstractButton.fireActionPerformed(AbstractButton.java:1995)
    at javax.swing.AbstractButton$Handler.actionPerformed(AbstractButton.java:2318)
    at javax.swing.DefaultButtonModel.fireActionPerformed(DefaultButtonModel.java:387)
    at javax.swing.DefaultButtonModel.setPressed(DefaultButtonModel.java:242)
    at javax.swing.plaf.basic.BasicButtonListener.mouseReleased(BasicButtonListener.java:236)
    at java.awt.Component.processMouseEvent(Component.java:6263)
    at javax.swing.JComponent.processMouseEvent(JComponent.java:3255)
    at java.awt.Component.processEvent(Component.java:6028)
    at java.awt.Container.processEvent(Container.java:2041)
    at java.awt.Component.dispatchEventImpl(Component.java:4630)
    at java.awt.Container.dispatchEventImpl(Container.java:2099)
    at java.awt.Component.dispatchEvent(Component.java:4460)
    at java.awt.LightweightDispatcher.retargetMouseEvent(Container.java:4574)
    at java.awt.LightweightDispatcher.processMouseEvent(Container.java:4238)
    at java.awt.LightweightDispatcher.dispatchEvent(Container.java:4168)
    at java.awt.Container.dispatchEventImpl(Container.java:2085)
    at java.awt.Window.dispatchEventImpl(Window.java:2475)
    at java.awt.Component.dispatchEvent(Component.java:4460)
    at java.awt.EventQueue.dispatchEvent(EventQueue.java:599)
    at java.awt.EventDispatchThread.pumpOneEventForFilters(EventDispatchThread.java:269)
    at java.awt.EventDispatchThread.pumpEventsForFilter(EventDispatchThread.java:184)
    at java.awt.EventDispatchThread.pumpEventsForHierarchy(EventDispatchThread.java:174)
    at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:169)
    at java.awt.EventDispatchThread.pumpEvents(EventDispatchThread.java:161)
    at java.awt.EventDispatchThread.run(EventDispatchThread.java:122)
    111824 - Port opened

    $ cat /var/lock/LCK..rfcomm1
    17000
    $ ps awux|grep 17000
    grin 17000 6.4 3.7 363336 78060 pts/1 Sl 14:33 0:09 java -Xmx192m -Djava.library.path=./lib/rxtx-2.1-7-bins-r2/Linux/i686-unknown-linux-gnu bt747.j2se_view.BT747Main

    otherwise the same hack works.

     
  • Mario De Weerd
    Mario De Weerd
    2010-02-24

    [ Internet issues required me to write this again:-( ]

    The issue seems to be in the RXTX library.

    We'll do 3 things:
    1) Activate RXTX internal debug features;
    2) Swap RXTX versions.
    3) Make the 'run_j2se.sh' more verbose so that we know what it is doing.

    1) Internal RXTX debug.
    The run_j2se.sh script has to be edited.
    Change:
    #CLASSPATH="${RXTXPATH}/RXTXcomm-debug.jar:$CLASSPATH"
    #DEBUG_OPTION='-Dgnu.io.log.mode=FILE_MODE'
    to (=remove the leading #):
    CLASSPATH="${RXTXPATH}/RXTXcomm-debug.jar:$CLASSPATH"
    DEBUG_OPTION='-Dgnu.io.log.mode=FILE_MODE'

    This will enable the possibility to enable internal debug messages and enable it. The file the messages are written to should be 'asdf'.

    2) Swap versions.
    You can try each version with debug active.
    a. No further changes of the script run_j2se.sh -> you are probably using RXTX 2.1.7
    b. To use 2.2pre, just before the line:
    RXTXLIBPATH="${RXTXPATH}/Linux/i686-unknown-linux-gnu"
    add
    RXTXPATH="${ROOT_DIR}/lib/rxtx-2.2pre2-bins"

    c. Get http://soft.arduino2.1.8.zip and unzip the content to the 'lib' subdirectory. 'rxtx-2.1.8-arduino' will be added.
    Before the line:
    RXTXLIBPATH="${RXTXPATH}/Linux/i686-unknown-linux-gnu"
    add:
    RXTXPATH="${ROOT_DIR}/lib/rxtx-2.1.8-arduino"

    In case a, b an c, do the test and observe. Rename the 'asdf' file after each trial to some representative name for the test.

    3) More verbose 'run_j2se.sh'. This is mainly to confirm the above changes.
    Change the first line of 'run_j2se.sh' to:
    #!/bin/sh -xv
    #(there should not be a space before the '#' token - indented here for clarity)
    I am interested in the last lines reported on execution to make sure that the paths are set correctly.

     
  • Mario De Weerd
    Mario De Weerd
    2010-02-24

    I added the 'dubious port' opening in 2.X.1685.

    I am still interested in testing results of the 2.X.1684 version if 1685 works. I've been looking through the code and chances are slim that I'll be fixing it - chances are that it is going to be quite some effort, but only the tests can fully confirm that.