RPi4 jSerialComm UnsatisfiedLinkError (Solarthing stopped working after installing updates)

[MarkSmurph]

Hi, I've been using solarthing for about a year and it's been working great - thanks for sharing your awesome work!

I installed some updates on the Raspberry Pi today and solarthing stopped working. Logs below.
Any ideas as to what is wrong?

Thanks,
Mark

2023-05-10 15:29:31.085 [main] INFO  me.retrodaredevil.solarthing.program.SolarMain - [LOG] Beginning main. Jar: Jar: solarthing-2023.2.0.jar Last Modified: 2023-03-11T23:11:53Z Java version: 11.0.18
2023-05-10 15:29:31.470 [main] INFO  me.retrodaredevil.solarthing.program.SolarMain - Running as pi
2023-05-10 15:29:31.471 [main] INFO  me.retrodaredevil.solarthing.program.SolarMain - Using base configuration file: config/base.json
2023-05-10 15:29:32.753 [main] INFO  me.retrodaredevil.solarthing.program.RequestMain - Beginning request program
2023-05-10 15:29:32.758 [main] INFO  me.retrodaredevil.solarthing.analytics.AnalyticsManager - Google Analytics is ENABLED!
2023-05-10 15:29:33.758 [main] INFO  me.retrodaredevil.solarthing.analytics.AnalyticsManager - Sending program type to Google Analytics
2023-05-10 15:29:34.685 [main] INFO  me.retrodaredevil.solarthing.program.PacketHandlerInit - Commands are disabled
2023-05-10 15:29:34.980 [main] INFO  me.retrodaredevil.solarthing.program.SolarMain - Got an UnsatisfiedLinkError which is uncommon. If setup correctly, after this crash program will relaunch (hopefully successfully).
2023-05-10 15:29:34.981 [main] ERROR me.retrodaredevil.solarthing.program.SolarMain - [LOG] Ending SolarThing. Jar: solarthing-2023.2.0.jar Last Modified: 2023-03-11T23:11:53Z Java version: 11.0.18
2023-05-10 15:29:34.982 [main] ERROR me.retrodaredevil.solarthing.program.SolarMain - (Fatal)Got throwable
java.lang.UnsatisfiedLinkError: /tmp/jSerialComm/1683728974974-libjSerialComm.so: /tmp/jSerialComm/1683728974974-libjSerialComm.so: cannot open shared object file: No such file or directory
	at java.lang.ClassLoader$NativeLibrary.load0(Native Method) ~[?:?]
	at java.lang.ClassLoader$NativeLibrary.load(ClassLoader.java:2445) ~[?:?]
	at java.lang.ClassLoader$NativeLibrary.loadLibrary(ClassLoader.java:2501) ~[?:?]
	at java.lang.ClassLoader.loadLibrary0(ClassLoader.java:2700) ~[?:?]
	at java.lang.ClassLoader.loadLibrary(ClassLoader.java:2630) ~[?:?]
	at java.lang.Runtime.load0(Runtime.java:768) ~[?:?]
	at java.lang.System.load(System.java:1837) ~[?:?]
	at com.fazecast.jSerialComm.SerialPort.<clinit>(SerialPort.java:248) ~[solarthing-2023.2.0.jar:?]
	at me.retrodaredevil.io.serial.JSerialIOBundle.createSerialPortFromName(JSerialIOBundle.java:77) ~[solarthing-2023.2.0.jar:?]
	at me.retrodaredevil.solarthing.config.io.SerialIOConfig.createIOBundle(SerialIOConfig.java:45) ~[solarthing-2023.2.0.jar:?]
	at me.retrodaredevil.solarthing.io.ReloadableIOBundle.reload(ReloadableIOBundle.java:56) ~[solarthing-2023.2.0.jar:?]
	at me.retrodaredevil.solarthing.io.ReloadableIOBundle.<init>(ReloadableIOBundle.java:31) ~[solarthing-2023.2.0.jar:?]
	at me.retrodaredevil.solarthing.config.request.modbus.ModbusDataRequester.create(ModbusDataRequester.java:51) ~[solarthing-2023.2.0.jar:?]
	at me.retrodaredevil.solarthing.program.RequestMain.lambda$startRequestProgram$1(RequestMain.java:53) ~[solarthing-2023.2.0.jar:?]
	at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:195) ~[?:?]
	at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1655) ~[?:?]
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:484) ~[?:?]
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:474) ~[?:?]
	at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:913) ~[?:?]
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) ~[?:?]
	at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:578) ~[?:?]
	at me.retrodaredevil.solarthing.program.RequestMain.startRequestProgram(RequestMain.java:54) ~[solarthing-2023.2.0.jar:?]
	at me.retrodaredevil.solarthing.program.RequestMain.startRequestProgram(RequestMain.java:40) ~[solarthing-2023.2.0.jar:?]
	at me.retrodaredevil.solarthing.program.SolarMain.doMainCommand(SolarMain.java:151) ~[solarthing-2023.2.0.jar:?]
	at me.retrodaredevil.solarthing.program.SolarMain.doMain(SolarMain.java:212) ~[solarthing-2023.2.0.jar:?]
	at me.retrodaredevil.solarthing.program.SolarMain.determineMainSubprogram(SolarMain.java:272) ~[solarthing-2023.2.0.jar:?]
	at me.retrodaredevil.solarthing.program.SolarMain.main(SolarMain.java:286) ~[solarthing-2023.2.0.jar:?]

[retrodaredevil]

Hmm. I've gotten that error before. If you restart your pi or restart solarthing does it go away? That's how I fixed the error when it appeared.

I'll look into this further if that doesn't fix it.

[MarkSmurph]

I've tried rebooting a few times and restarting solarthing, but to no avail.
Running systemctl status solarthing-* usually says it's running, but it restarts every few seconds.
I caught it before it restarted this time...

● solarthing-custom_rover.service - The service for SolarThing custom_rover
     Loaded: loaded (/etc/systemd/system/solarthing-custom_rover.service; enabled; vendor preset: enabled)
     Active: active (running) since Wed 2023-05-10 17:15:51 BST; 5s ago
   Main PID: 4353 (sh)
      Tasks: 22 (limit: 3933)
        CPU: 6.905s
     CGroup: /system.slice/solarthing-custom_rover.service
             ├─4353 sh /opt/solarthing/program/custom_rover/run.sh
             ├─4355 sh ../.scripts/solarthing.sh
             ├─4357 bash ../.scripts/../.bin/local_log_solarthing run --base config/base.json
             ├─4363 sh ../.scripts/../.bin/../.bin/raw_solarthing run --base config/base.json
             └─4367 java --add-opens=java.base/java.lang.invoke=ALL-UNNAMED -jar ../.scripts/../.bin/../.bin/../solarthing.jar run --base config/base.json

May 10 17:15:51 ShedPi systemd[1]: Started The service for SolarThing custom_rover.
May 10 17:15:58 ShedPi systemd[1]: solarthing-custom_rover.service: Main process exited, code=exited, status=211/IOPRIO
May 10 17:15:58 ShedPi systemd[1]: solarthing-custom_rover.service: Failed with result 'exit-code'.
May 10 17:15:58 ShedPi systemd[1]: solarthing-custom_rover.service: Consumed 11.835s CPU time.

[retrodaredevil]

There are a few possible issues that this relates to: (leaving these here for documentation purposes, you can ignore them)

• UnsatisfiedLinkError : cannot open shared object file Fazecast/jSerialComm#313 (comment)
  • May need to specify -Dos.arch_full=armv7-hf in command line parameters.
• tmp Directory Creation Fazecast/jSerialComm#486 (comment)
  • May need to do System.setProperty("fazecast.jSerialComm.appid", "YOUR_APPLICATION_IDENTIFIER"). (Unlikely to be the problem unless you are running multiple SolarThing instances)

Linking this relevant issue: #74

---

Can you run uname -a and paste its output? What kind of Raspberry Pi do you have? Can you run ls -la /tmp/jSerialComm/ and paste its output? I want to see if the permissions on that temporary directory are weird for any reason.

Secondly, have you always run SolarThing using the pi user or were you just doing that to see the output of the program more easily? If you normally run SolarThing using the solarthing user (configured by default for systemd setups), can you see if the output is any different when doing sudo -u solarthing ./run.sh rather than just ./run.sh. Alternatively, you can just let the systemd service crash and then look in the logs directory inside /opt/solarthing/program/custom_rover/logs/log_info.log and confirm the error is the same as above.

As a worse case scenario, I can update SolarThing to allow the option to use a different serial library. I think I had that option a while back but I scrapped it when I realized I didn't need it anymore.

[MarkSmurph]

Thanks for looking into this.
It's a Pi 4 Model B
uname -a gives

Linux ShedPi 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr  3 17:24:16 BST 2023 aarch64 GNU/Linux

Output of ls -la /tmp/jSerialComm/:

total 8
drwxrwxrwx  2 solarthing solarthing 4096 May 10 18:22 .
drwxrwxrwt 20 root       root       4096 May 10 18:22 ..

I have always used pi. Just tried running as solarthing and got the same error.

[retrodaredevil]

Alright I want you to try a couple of things. I suspect this has something to do with the arm64 architecture. I want to try to modify some of the arguments being passed to the java command so first, as a control, I'll have you run this:

pi@ShedPi:/opt/solarthing/program/custom_rover$ java --add-opens=java.base/java.lang.invoke=ALL-UNNAMED -jar ../solarthing.jar config/base.json

That should give you the same error. Now I want you to try to run this:

java --add-opens=java.base/java.lang.invoke=ALL-UNNAMED -Dos.arch_full=armv8_64 -jar ../solarthing.jar run --base config/base.json

If that gives you the same error I want you to try this:

java --add-opens=java.base/java.lang.invoke=ALL-UNNAMED -Dos.arch_full=armv8_32 -jar ../solarthing.jar run --base config/base.json

If that still does not work, try this command:

java --add-opens=java.base/java.lang.invoke=ALL-UNNAMED -Dos.arch_full=armv7-hf -jar ../solarthing.jar run --base config/base.json

And then also try this:

java --add-opens=java.base/java.lang.invoke=ALL-UNNAMED -Dos.arch_full=armv7 -jar ../solarthing.jar run --base config/base.json

Notice I am just changing this: -Dos.arch_full=arm*** in the above commands. I'm not sure if it's going to fix it, but it's worth a shot. (This relates to Fazecast/jSerialComm#313)

Ideally one of those commands will work and I can either report a but in jSerialComm or create some sort of workaround in SolarThing.

[MarkSmurph]

All of those give errors, including the following:

Unknown argument: config/base.json

I suspect there's a flag missing?

[retrodaredevil]

That's my bad. Before that argument you need to include run --base config/base.json. I'll update my comment now.

[MarkSmurph]

Ooh! Looks like -Dos.arch_full=armv7-hf did it!
Thank you so much!
Now, how do I make that stick?

[retrodaredevil]

Now, how do I make that stick?

As a temporary solution, you could add that argument inside of /opt/solarthing/program/.bin/raw_solarthing to both java commands (really only the one with --add-opens is important since you are using Java >= 9). Then you can restart the service as normal and it should work. You can confirm that argument is present when running systemctl status solarthing-custom_rover.

This has the downside of potentially causing a merge conflict if I change that file and you run git pull, but I will try to send something here before I do that. I think this is a bug in jSerialComm. I'm not sure what the best course of action is for a more permanent fix, but I'll keep this issue open and will eventually look into it.

[MarkSmurph]

Brilliant, I'm back up and running. Cheers for your help, I've thrown a pint or two your way :)

[retrodaredevil]

Thanks for the donation 😄. I'm going to reopen this issue as it's something I need to come back to. I believe more RPi4s may be affected by this. Glad your setup is working, though.