search

wildmountainfarms / solarthing

Monitors an Outback MATE, Renogy Rover - MPPT Charge Controller and EPEver Tracer. Integrates with Grafana, PVOutput and more!
https://solarthing.readthedocs.io
MIT License
131 stars 28 forks source link

RPi4 jSerialComm UnsatisfiedLinkError (Solarthing stopped working after installing updates) #122

Open MarkSmurph opened 1 year ago

MarkSmurph commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

Linking this relevant issue: https://github.com/wildmountainfarms/solarthing/issues/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 commented 1 year ago

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 commented 1 year ago

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 https://github.com/Fazecast/jSerialComm/issues/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 commented 1 year ago

All of those give errors, including the following:

Unknown argument: config/base.json

I suspect there's a flag missing?

retrodaredevil commented 1 year ago

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

MarkSmurph commented 1 year ago

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

retrodaredevil commented 1 year ago

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 commented 1 year ago

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

retrodaredevil commented 1 year ago

Thanks for the donation :smile:. 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.

retrodaredevil commented 8 months ago

@MarkSmurph I was curious if you had any problems with this since you got it working?

MarkSmurph commented 8 months ago

No, it's worked flawlessly since you sent me the fix. Thanks!