myrobotlab icon indicating copy to clipboard operation
myrobotlab copied to clipboard

Published 20 hours ago • verified publisher icon MyRobotLab

RasPi service not working on latest develop

Open nickschiffer opened this issue 6 years ago • 5 comments

Upon attempting to createAndStart a Raspi instance, a nullpointer exception is thrown. This same method of creating a RasPi instance works on master

To Reproduce Steps to reproduce the behavior: Create a RasPi instance through the GUI or through python

Raspberry Pi 4 (please complete the following information):

  • OS: DietPi (Raspberry Pi 4)

LOG myrobotlab.log

22:22:48.804 [main] INFO c.m.s.Runtime [Runtime.java:354] services [log, Log, gui, SwingGui, python, Python]
22:22:48.812 [main] INFO c.m.s.Runtime [Runtime.java:362] attempting to invoke : log of type Log
22:22:48.813 [main] INFO c.m.s.Runtime [Runtime.java:385] Runtime.createService log
22:22:48.837 [main] INFO c.m.f.MethodCache [MethodCache.java:163] caching Runtime's 337 methods and 170 declared methods
22:22:48.920 [main] INFO c.m.f.MethodCache [MethodCache.java:226] cached Runtime 337 methods with 321 ordinal signatures in 97 ms
22:22:49.013 [main] INFO c.m.f.r.ServiceData [ServiceData.java:89] Returning serviceData.json from data/.myrobotlab/serviceData.json
22:22:49.015 [main] INFO c.m.f.r.Repo [Repo.java:93] create repo libraries
22:22:49.022 [main] INFO c.m.f.r.Repo [Repo.java:422] loading libraries/repo.json
22:22:49.029 [main] INFO c.m.f.r.Repo [Repo.java:449] loaded libraries/repo.json
22:22:49.029 [main] INFO c.m.i.FileIO [FileIO.java:1171] looking for Resource framework/ivy.xml.template
22:22:49.031 [main] INFO c.m.i.FileIO [FileIO.java:1171] looking for Resource framework/ivysettings.xml.template
22:22:49.033 [main] INFO c.m.s.Runtime [Runtime.java:1811] ============== args begin ==============
22:22:49.034 [main] INFO c.m.s.Runtime [Runtime.java:1823] jvmArgs [-Djava.library.path=libraries/native, -Djna.library.path=libraries/native, -Dfile.encoding=UTF-8]
22:22:49.035 [main] INFO c.m.s.Runtime [Runtime.java:1825] file.encoding UTF-8
22:22:49.036 [main] INFO c.m.s.Runtime [Runtime.java:1826] args [--service, log, Log, gui, SwingGui, python, Python, --id, victorious-calculon, --data-dir, data, --log-level, info, --spawned-from-agent]
22:22:49.036 [main] INFO c.m.s.Runtime [Runtime.java:1828] ============== args end ==============
22:22:49.036 [main] INFO c.m.s.Runtime [Runtime.java:1830] ============== env begin ==============
22:22:49.039 [main] INFO c.m.s.Runtime [Runtime.java:1834] PATH=/opt/ros/melodic/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/local/games:/usr/games
22:22:49.040 [main] INFO c.m.s.Runtime [Runtime.java:1841] JAVA_HOME not defined
22:22:49.040 [main] INFO c.m.s.Runtime [Runtime.java:1850] PROCESSOR_ARCHITECTURE not defined
22:22:49.041 [main] INFO c.m.s.Runtime [Runtime.java:1855] PROCESSOR_ARCHITEW6432 not defined
22:22:49.041 [main] INFO c.m.s.Runtime [Runtime.java:1857] ============== env end ==============
22:22:49.041 [main] INFO c.m.s.Runtime [Runtime.java:1860] ============== normalized ==============
22:22:49.042 [main] INFO c.m.s.Runtime [Runtime.java:1862] 2019/10/24 22:22:48 - GMT - 2019/10/25 05:22:48
22:22:49.043 [main] INFO c.m.s.Runtime [Runtime.java:1863] pid 1494
22:22:49.044 [main] INFO c.m.s.Runtime [Runtime.java:1864] hostname dietpi
22:22:49.044 [main] INFO c.m.s.Runtime [Runtime.java:1865] ivy [runtime,armv7.hfp.32.linux]
22:22:49.045 [main] INFO c.m.s.Runtime [Runtime.java:1866] version 1.8.0_212 branch unknownBranch commit unknownCommit build null
22:22:49.046 [main] INFO c.m.s.Runtime [Runtime.java:1867] platform [armv7.hfp.32.linux}]
22:22:49.046 [main] INFO c.m.s.Runtime [Runtime.java:1868] version [1.8.0_212]
22:22:49.047 [main] INFO c.m.s.Runtime [Runtime.java:1869] root [/home/nick/MRL_NEW/myrobotlab-unknownBranch-1.8.0_212.jar]
22:22:49.047 [main] INFO c.m.s.Runtime [Runtime.java:1870] cfg dir [data/.myrobotlab]
22:22:49.059 [main] INFO c.m.s.Runtime [Runtime.java:1871] sun.arch.data.model [32]
22:22:49.060 [main] INFO c.m.s.Runtime [Runtime.java:1873] ============== non-normalized ==============
22:22:49.061 [main] INFO c.m.s.Runtime [Runtime.java:1874] os.name [Linux] getOS [linux]
22:22:49.062 [main] INFO c.m.s.Runtime [Runtime.java:1875] os.arch [arm] getArch [armv7.hfp]
22:22:49.063 [main] INFO c.m.s.Runtime [Runtime.java:1876] os.version [4.19.75-v7l+]
22:22:49.064 [main] INFO c.m.s.Runtime [Runtime.java:1878] java.vm.name [OpenJDK Client VM]
22:22:49.064 [main] INFO c.m.s.Runtime [Runtime.java:1879] java.vm.vendor [Oracle Corporation]
22:22:49.065 [main] INFO c.m.s.Runtime [Runtime.java:1880] java.specification.version [1.8]
22:22:49.065 [main] INFO c.m.s.Runtime [Runtime.java:1883] file.encoding [UTF-8]
22:22:49.066 [main] INFO c.m.s.Runtime [Runtime.java:1884] Charset.defaultCharset() [UTF-8]
22:22:49.067 [main] INFO c.m.s.Runtime [Runtime.java:1885] user.language [en]
22:22:49.068 [main] INFO c.m.s.Runtime [Runtime.java:1886] user.country [US]
22:22:49.070 [main] INFO c.m.s.Runtime [Runtime.java:1887] user.variant [null]
22:22:49.071 [main] INFO c.m.s.Runtime [Runtime.java:1891] java.home [/usr/lib/jvm/java-8-openjdk-armhf/jre]
22:22:49.072 [main] INFO c.m.s.Runtime [Runtime.java:1893] java.library.path [libraries/native]
22:22:49.072 [main] INFO c.m.s.Runtime [Runtime.java:1894] user.dir [/home/nick/MRL_NEW]
22:22:49.072 [main] INFO c.m.s.Runtime [Runtime.java:1896] user.home [/home/nick]
22:22:49.073 [main] INFO c.m.s.Runtime [Runtime.java:1897] total mem [15] Mb
22:22:49.073 [main] INFO c.m.s.Runtime [Runtime.java:1898] total free [9] Mb
22:22:49.074 [main] INFO c.m.s.Runtime [Runtime.java:1910] getting local repo
22:22:49.077 [main] INFO c.m.s.Runtime [Runtime.java:385] Runtime.createService security
22:22:49.086 [main] INFO c.m.f.MethodCache [MethodCache.java:163] caching Security's 199 methods and 33 declared methods
22:22:49.104 [main] INFO c.m.f.MethodCache [MethodCache.java:226] cached Security 199 methods with 187 ordinal signatures in 23 ms
22:22:49.108 [main] INFO c.m.s.Security [Security.java:294] Security.loadStore file not found data/Security/store
22:22:49.115 [main] INFO c.m.i.FileIO [FileIO.java:415] Resources aleady exist: not extracting -- Dir : /home/nick/MRL_NEW/resource Jar : resource
22:22:49.122 [main] INFO c.m.f.MethodCache [MethodCache.java:163] caching Log's 201 methods and 35 declared methods
22:22:49.138 [main] INFO c.m.f.MethodCache [MethodCache.java:226] cached Log 201 methods with 186 ordinal signatures in 19 ms
22:23:08.176 [runtime] ERROR c.m.s.Runtime [Runtime.java:430] createService failed
java.lang.reflect.InvocationTargetException: null
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_212]
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_212]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_212]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_212]
	at org.myrobotlab.framework.Instantiator.getThrowableNewInstance(Instantiator.java:54) ~[myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	at org.myrobotlab.service.Runtime.createService(Runtime.java:422) [myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	at org.myrobotlab.service.Runtime.create(Runtime.java:302) [myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	at org.myrobotlab.service.Runtime.createAndStart(Runtime.java:331) [myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_212]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_212]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_212]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_212]
	at org.myrobotlab.framework.Service.invokeOn(Service.java:1408) [myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	at org.myrobotlab.framework.Service.invoke(Service.java:1372) [myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	at org.myrobotlab.framework.Service.run(Service.java:1744) [myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_212]
Caused by: java.lang.UnsatisfiedLinkError: com.pi4j.wiringpi.Gpio.wiringPiSetup()I
	at com.pi4j.wiringpi.Gpio.wiringPiSetup(Native Method) ~[pi4j-core-1.2-20190226.164806-39.jar:na]
	at com.pi4j.io.gpio.RaspiGpioProvider.<init>(RaspiGpioProvider.java:69) ~[pi4j-core-1.2-20190226.164806-39.jar:na]
	at com.pi4j.io.gpio.RaspiGpioProvider.<init>(RaspiGpioProvider.java:51) ~[pi4j-core-1.2-20190226.164806-39.jar:na]
	at com.pi4j.platform.Platform.getGpioProvider(Platform.java:125) ~[pi4j-core-1.2-20190226.164806-39.jar:na]
	at com.pi4j.platform.Platform.getGpioProvider(Platform.java:118) ~[pi4j-core-1.2-20190226.164806-39.jar:na]
	at com.pi4j.io.gpio.GpioFactory.getDefaultProvider(GpioFactory.java:109) ~[pi4j-core-1.2-20190226.164806-39.jar:na]
	at com.pi4j.io.gpio.impl.GpioControllerImpl.<init>(GpioControllerImpl.java:53) ~[pi4j-core-1.2-20190226.164806-39.jar:na]
	at com.pi4j.io.gpio.GpioFactory.getInstance(GpioFactory.java:91) ~[pi4j-core-1.2-20190226.164806-39.jar:na]
	at org.myrobotlab.service.RasPi.<init>(RasPi.java:115) ~[myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	... 16 common frames omitted
22:23:08.178 [runtime] ERROR c.m.f.Service [Service.java:2147] runtime error createAndStart(Raspi, org.myrobotlab.service.RasPi) java.lang.NullPointerException
22:23:08.180 [runtime] ERROR c.m.s.Runtime [Runtime.java:336] createAndStart(Raspi, org.myrobotlab.service.RasPi) java.lang.NullPointerException
java.lang.NullPointerException: null
	at org.myrobotlab.service.Runtime.createAndStart(Runtime.java:332) ~[myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_212]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_212]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_212]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_212]
	at org.myrobotlab.framework.Service.invokeOn(Service.java:1408) [myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	at org.myrobotlab.framework.Service.invoke(Service.java:1372) [myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	at org.myrobotlab.framework.Service.run(Service.java:1744) [myrobotlab-unknownBranch-1.8.0_212.jar:1.1.${BUILD_NUMBER}]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_212]

nickschiffer avatar Oct 26 '19 19:10 nickschiffer

Here's an additional log message that may be helpful:

Oct 25, 2019 2:10:40 AM com.pi4j.util.NativeLibraryLoader load SEVERE: Unable to load [libpi4j.so] using path: [/lib/raspberrypi/dynamic/libpi4j.so] java.lang.UnsatisfiedLinkError: /tmp/libpi4j636337189176564383.so: libwiringPi.so: cannot open shared object file: No such file or directory at java.lang.ClassLoader$NativeLibrary.load(Native Method) at java.lang.ClassLoader.loadLibrary0(ClassLoader.java:1941) at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1824) at java.lang.Runtime.load0(Runtime.java:809) at java.lang.System.load(System.java:1086) at com.pi4j.util.NativeLibraryLoader.loadLibraryFromClasspath(NativeLibraryLoader.java:159) at com.pi4j.util.NativeLibraryLoader.load(NativeLibraryLoader.java:105) at com.pi4j.wiringpi.Gpio.(Gpio.java:189) at com.pi4j.io.gpio.RaspiGpioProvider.(RaspiGpioProvider.java:69) at com.pi4j.io.gpio.RaspiGpioProvider.(RaspiGpioProvider.java:51) at com.pi4j.platform.Platform.getGpioProvider(Platform.java:125) at com.pi4j.platform.Platform.getGpioProvider(Platform.java:118) at com.pi4j.io.gpio.GpioFactory.getDefaultProvider(GpioFactory.java:109) at com.pi4j.io.gpio.impl.GpioControllerImpl.(GpioControllerImpl.java:53) at com.pi4j.io.gpio.GpioFactory.getInstance(GpioFactory.java:91) at org.myrobotlab.service.RasPi.(RasPi.java:115) at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:423) at org.myrobotlab.framework.Instantiator.getThrowableNewInstance(Instantiator.java:54) at org.myrobotlab.service.Runtime.createService(Runtime.java:422) at org.myrobotlab.service.Runtime.create(Runtime.java:302) at org.myrobotlab.service.Runtime.createAndStart(Runtime.java:331) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.myrobotlab.framework.Service.invokeOn(Service.java:1408) at org.myrobotlab.framework.Service.invoke(Service.java:1372) at org.myrobotlab.framework.Service.run(Service.java:1744) at java.lang.Thread.run(Thread.java:748)

nickschiffer avatar Oct 26 '19 22:10 nickschiffer

Hi Nick, I suspect that its an incompatibility between gcc versions of the raspi dependency we pull in vs what you have on a more recent image .. It can be updated in the pom or preferrably, updated in the RasPi.getMetaData method..

I've got a raspi 1b I'm turning into a media center .. I'll do some experiments on the latest raspian/omsc image

supertick avatar Oct 27 '19 17:10 supertick

I see. Is this not related to the pi4j version in the pom? I tried compiling with 1.1,2,3 SNAPSHOTS and added the gpio extension as well with the same error. Strange that the pi4j 1.1 works just fine on the Pi4 even though it isn't technically supported until pi4j 1.3. Also, is wiringPi part of pi4j? I didn't see it in the older build.xml or the newer pom.xml.

nickschiffer avatar Oct 27 '19 18:10 nickschiffer

I now have the latest omsc installed on my ancient raspi 1 .. I'll bump the verion of raspi4j to the latest ... and test

hmmm ... perhaps it just "needs" the natives "com.pi4j", "pi4j-native", "1.2"

supertick avatar Oct 27 '19 19:10 supertick

I see 1.2, 1.3 & 1.4 shapshot versions in maven central with only 1.1 release version (a little strange) I added 1.2 snapshot core & native to the & RasPi.getMetaData - I don't get a "native" error but I do get a invalid bus number error - the service is asking for bus 1 on a raspi 1b I'm guessing it might not have a bus 1 only a bus 0 ? (more testing needed)

supertick avatar Oct 31 '19 01:10 supertick