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);

[jakkarth]

If you have the ability to run JabRef under a debugger, and you can reproduce this scenario, I'd be really interested to see what the code flow is starting from

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

Line 139 in 082e9cf

RemotePreferences remotePreferences = preferences.getRemotePreferences();

maybe.

[Siedlerchr]

I can try to debug this later (having a mac here), if you want to debug this in an IDE just follow our guide for setting up a workspace https://devdocs.jabref.org/getting-into-the-code/guidelines-for-setting-up-a-local-workspace.html

[jakkarth]

I don't have enough free disk space to fit an IntelliJ install on this machine, so for the time being the best I can do is look at the repo on github and ask nicely :)

[jakkarth]

I bought a new hard drive with more space and spent a few hours working through that document getting the environment set up. It took a lot of work, though some of that was because my machine started from a bad state.

Anyway, I've replicated things as best I can while debugging the (second) instance of JabRef, and there is indeed a network timeout trying to connect to the first instance. I am at a loss to explain how it could possibly take longer than 0.2 seconds to establish a network connection to localhost.

So, I can confirm #8653 (comment), but I'm at a loss to explain it. Increasing the timeout hasn't fixed the underlying problem, but has kept it from occurring on my machine. At this point I'm satisfied that the ping code is in fact executing, but I hate the unsolved mystery of why 0.2s isn't sufficient.

I propose increasing the timeout to 1000 as @Siphalor suggested. I would also suggest catching the java.net.BindException: Address already in use and showing the user a friendlier message about the two potential causes: 1, another application is already using this port and they should pick a different one for JabRef, or 2, the timeout value wasn't long enough for their circumstances, in which case we could suggest they file a bug with additional info.

Now that I have a local environment where I can actually make those changes, I'd be happy to make a MR. Thoughts?

[Siedlerchr]

Thanks for investigating this issue! We really appreciate this! Really a mystery. Could be that the JVM is taking some extra time until the connection is open. If increasing the timeout works, we should take that easy route!
Go ahead with your PR!

[jakkarth]

PR created. This is my first time contributing to this project. I read through the contribution guidelines and I think I got them all, but I'm happy to fix anything I missed. Your patience is appreciated :)