JabRef opens multiple instances even when Remote operation is enabled

[jakkarth]

JabRef version

Latest development branch build (please note build date below)

Operating system

GNU / Linux

Details on version and operating system

Linux Mint 20.1 MATE, JabRef 5.6--2022-04-04--dbf921e

Checked with the latest development build

• I made a backup of my libraries before testing the latest development version.
• I have tested the latest development version and the problem persists

Steps to reproduce the behaviour

0. Read documentation on this feature at https://docs.jabref.org/advanced/remote
1. Open JabRef
2. Under Options -> Preferences, Network, check the "Listen for remote operation on port" box and make sure 6050 is entered.
3. Save the settings, optionally restart the application.
4. Using netstat -lpnt |grep 6050 confirm that the port is properly opened by the java process
5. Attempt to open an additional copy of JabRef, either by launching the application or by using the browser extension to import a new reference.

Expected behavior: based on the documentation saying "Binding to this port makes it possible for a second JabRef instance to discover that the first one is running. In this case, unless specifically instructed to run in stand-alone mode, the second JabRef instance will pass its command line options through the port to the first JabRef instance, and then immediately quit." (emphasis added).

Actual behavior: When importing from the browser extension, a new instance of JabRef is opened and stays open. When launched from a console, WARN: Port is blocked: java.net.BindException: Address already in use is shown in the console of the second JabRef instance, and the application opens and stays open.

Appendix

...

Log File

Apr 07, 2022 2:32:20 PM com.sun.javafx.application.PlatformImpl startup
WARNING: Unsupported JavaFX configuration: classes were loaded from 'module org.jabref.merged.module', isAutomatic: false, isOpen: true
2022-04-07 14:32:21 [JavaFX Application Thread] org.jabref.logic.net.ssl.TrustStoreManager.createTruststoreFileIfNotExist()
INFO: Trust store path: /home/jakkarth/.local/share/ssl/truststore.jks
2022-04-07 14:32:22 [JavaFX Application Thread] org.jabref.logic.remote.server.RemoteListenerServerLifecycle.open()
WARN: Port is blocked: java.net.BindException: Address already in use
	at java.base/sun.nio.ch.Net.bind0(Native Method)
	at java.base/sun.nio.ch.Net.bind(Unknown Source)
	at java.base/sun.nio.ch.Net.bind(Unknown Source)
	at java.base/sun.nio.ch.NioSocketImpl.bind(Unknown Source)
	at java.base/java.net.ServerSocket.bind(Unknown Source)
	at java.base/java.net.ServerSocket.<init>(Unknown Source)
	at org.jabref@5.6.144/org.jabref.logic.remote.server.RemoteListenerServer.<init>(Unknown Source)
	at org.jabref@5.6.144/org.jabref.logic.remote.server.RemoteListenerServerThread.<init>(Unknown Source)
	at org.jabref@5.6.144/org.jabref.logic.remote.server.RemoteListenerServerLifecycle.open(Unknown Source)
	at org.jabref@5.6.144/org.jabref.logic.remote.server.RemoteListenerServerLifecycle.openAndStart(Unknown Source)
	at org.jabref@5.6.144/org.jabref.gui.JabRefMain.handleMultipleAppInstances(Unknown Source)
	at org.jabref@5.6.144/org.jabref.gui.JabRefMain.start(Unknown Source)
	at org.jabref.merged.module@5.6.144/com.sun.javafx.application.LauncherImpl.lambda$launchApplication1$9(Unknown Source)
	at org.jabref.merged.module@5.6.144/com.sun.javafx.application.PlatformImpl.lambda$runAndWait$12(Unknown Source)
	at org.jabref.merged.module@5.6.144/com.sun.javafx.application.PlatformImpl.lambda$runLater$10(Unknown Source)
	at java.base/java.security.AccessController.doPrivileged(Unknown Source)
	at org.jabref.merged.module@5.6.144/com.sun.javafx.application.PlatformImpl.lambda$runLater$11(Unknown Source)
	at org.jabref.merged.module@5.6.144/com.sun.glass.ui.InvokeLaterDispatcher$Future.run(Unknown Source)
	at org.jabref.merged.module@5.6.144/com.sun.glass.ui.gtk.GtkApplication._runLoop(Native Method)
	at org.jabref.merged.module@5.6.144/com.sun.glass.ui.gtk.GtkApplication.lambda$runLoop$11(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)

[Siphalor]

I think I found the issue, at least I found a fix for me locally.
It seems to boil down to the socket being too slow for the maximum timeout.

Experimenting with various timeouts, 1000 instead of 200 seems to be working reliably for me.

A fix would be to either just bump the timeout to that or to make it configurable.

Current code:

jabref/src/main/java/org/jabref/logic/remote/client/RemoteClient.java

Line 21 in ca68049

private static final int TIMEOUT = 200;

[jakkarth]

Experimenting with various timeouts, 1000 instead of 200 seems to be working reliably for me.

I'm not convinced a timeout is the issue here. The port is responsive for me in far less than 200ms:

> time echo 'foo' | nc localhost 6050
��
real 0m0.005s
user 0m0.002s
sys 0m0.003s

As a side note, testing it that way results in a stack trace:

WARN: RemoteListenerServer crashed: java.io.StreamCorruptedException: invalid stream header: 666F6F0A

[jakkarth]

This is still an issue for me using JabRef 5.6--2022-04-25--5c9d898.

[jakkarth]

Additional investigation of this issue has occurred at JabRef/JabRef-Browser-Extension#443.

[jakkarth]

This issue is still occurring for me when using the latest development build I could find:

JabRef 5.7--2022-06-06--082e9cf
Linux 5.4.0-113-generic amd64
Java 18.0.1
JavaFX unknown

I can confirm that the port is still being opened:

$ netstat -lpnt |grep -i java
tcp6 0 0 127.0.0.1:6050 :::* LISTEN 351921/java

Nevertheless, new executions from CLI still show WARN: Port is blocked: java.net.BindException: Address already in use, and launch a new instance. A new instance is also still launched from the browser extensions in chrome and firefox.

[ThiloteE]

This issue is beyond me, but having a look at the code and your description of the problem: Have you tried experimenting with different ports? If the issue persists with ports you know are NOT in usage by other programs, maybe JabRef detects its own listener on the port as "Address already in usage"?

[jakkarth]

This issue is beyond me, but having a look at the code and your description of the problem: Have you tried experimenting with different ports? If the issue persists with ports you know are NOT in usage by other programs, maybe JabRef detects its own listener on the port as "Address already in usage"?

I've just tried it with 6052 just in case there was some weird magic going on. It did not make a difference. The output of the netstat command above is showing that JabRef is the one with the port open. Before opening the first JabRef instance and after closing the last one, the port is not in use. There's no other process trying to use that port.

Can you point me in the code to where this functionality lives? Maybe I'll be able to spot something. I don't have the ability to compile the code and run it locally for debugging at the moment, but examining the code may yield clues.

[Siedlerchr]

@jakkarth The code is located here https://github.com/JabRef/jabref/tree/main/src/main/java/org/jabref/logic/remote
JabRef opens a socket (aka server) and also checks for the open socket as client

[jakkarth]

Thanks, this is interesting. At

jabref/src/main/java/org/jabref/gui/JabRefMain.java

Line 143 in 082e9cf

if (remoteClient.ping()) {

we see it attempting to ping an existing JabRef instance if one exists. Within the code for ping, we should see some output if the ping was unsuccessful, and back in JabRefMain we would proceed to making the server socket. I don't see any of the ping-related output though. It's like the ping is failing silently, and the else on 154 is being executed in the second instance just like it was in the first.

To confirm that the port is in fact open by JabRef, I created the following test program (rename to .java). Obviously it's not using the JabRef protocol, but executing this creates the connection successfully to the first JabRef instance, and that instance outputs some errors when I send bad data, so it's definitely talking to the right process.

Test.txt

[jakkarth]

Using wireshark, I've observed the traffic on the loopback address. When running my test program above, data is sent over the wire to the first JabRef instance. When launching a second JabRef instance, no data is sent. Based on that, I don't believe that

jabref/src/main/java/org/jabref/logic/remote/client/RemoteClient.java

Line 30 in 082e9cf

protocol.sendMessage(RemoteMessage.PING);

is being executed. But the output clearly shows that we are executing JabRefMain line 154. I don't understand how this can happen based on the source code.

[Siedlerchr]

Maybe the answer we get from the ping is not correct?

[jakkarth]

Maybe the answer we get from the ping is not correct?

I would expect to get error output if the response from the ping was received but not as expected:

jabref/src/main/java/org/jabref/logic/remote/client/RemoteClient.java

Line 38 in 082e9cf

LOGGER.error(errorMessage);