GPIO binding problem after OpenHAB restart

[Konstantin Polychronov]

Hi all,

I play around with GPIOs these days and I got into something which may appear to be a bug or maybe a wrong interpretation by me of how device pins are used.
I'm using it on beaglebone black rev.B

When you start the server for the first time all works OK. Binding is set and pin value is changing (0/1) when you change the switch item condition.

When you shutdown the openhab server though the pin still stays exported under /sys/class/gpio and after another start/restart of OpenHAB the following appears in the logs and the pin is no longer usable:
05:28:54.237 DEBUG o.o.b.g.i.GPIOBindingActivator[:30] - GPIO binding has been started.
05:32:59.803 DEBUG o.o.m.i.i.GenericItemProvider[:334] - Start processing binding configuration of Item 'AQ_Heater1 (Type=SwitchItem, State=Uninitialized)' with 'GPIOGenericBindingProvider' reader.
05:33:04.092 ERROR o.o.b.g.internal.GPIOBinding[:353] - Error occured while creating backend object for item AQ_Heater1, exception: Device or resource busy

AQ_Heater1 is a switch item in this case bind to my GPIO pin 60.
If I do the following:
1.manually stop OpenHAB
2. echo 60 > /sys/class/gpio/unexport  (i.e. unexport the pin)
3. Start again OpenHAB

GPIO pin 60 got exported by OpenHAB normally and works again OK.

Cheers,
K.

[Konstantin Polychronov]

For anyone who might need a workaround and is not deep into linux I've created a simple bash script under my openhab directory called unexportGPIOs which has the following type of rows:
echo <GPIO number> > /sys/class/gpio/unexport  
for each usable GPIO there is a row with the appropriate number.

Cheers,
K.

[Thomas Eichstädt-Engelen]

Hi Konstantin,

thanks for investigating this in detail!

Could you also provide a fix in (Java) code for the GPIO binding?

Best, Thomas E.-E.

--
You received this message because you are subscribed to the Google Groups "openhab" group.
To unsubscribe from this group and stop receiving emails from it, send an email to openhab+u...@googlegroups.com.
To post to this group, send email to ope...@googlegroups.com.
Visit this group at http://groups.google.com/group/openhab.
For more options, visit https://groups.google.com/d/optout.

[Konstantin Polychronov]

Sorry Thomas. I'm a humble IT admin guy. Not a java developer. :)I've provided workaround in the OS part which looks OK.

I'm not sure how the Jetty and Open HAB system does shutdown when you restart the service and not sure how you can handle this inside.
Probably when you initialize the GPIOs you need to first unexport the pins that you intend to use before you export them again.
Not sure if this will not violate something else though .... for example if you bind a wrong GPIO in openhab you may unexport a pin which is used for something else like eMMC or HDMI :)
On the other hand if you intend to use wrong GPIO nothing can stop you from doing so :)

Cheers, K.

[dpsl...@gmail.com]

Hi Konstantin,

How you are restarting openHAB? For me this looks that openHAB is killed (with TERM) instead of gracefully shut down or for some reason the binding isn't stopped in normal way. If everything is correct the binding should "unexport" the pins which it was using. I intentionally didn't implemented pin configuration overwrite on new pin creation, GPIO subsystem is a shared resource and openHAB can't assume that it's the only which is using it. If in normal conditions this happens it will means that either there is another system using this pin or there is a configuration error which must be solved manually instead of automatically.

[Konstantin Polychronov]

Hi,
I've created a systemd configuration for openhab as described here: http://tuxtec.blogspot.com/2013/11/installing-openhab-on-beaglebone-black.html (topic 4)
I usually shut it down with systemctl stop/restart openhab.service
If there is more graceful way I would be happy to use it.

I understand that you cannot unexport all pins that are in use. What I did as a workaround is a very simple script with listed pins "that I know" are working and I unexport them before the start of the app.

Cheers,
K.

[dpsl...@gmail.com]

Just for the records, in my previous reply I meant killed with "KILL" not with "TERM" signal, "TERM" will do graceful shutdown.

I need to test your configuration but at first glance it seems that you are hitting a timeout in systemd and openHAB is KILL-ed before full shutdown. On low-powered devices such as BBB openHAB takes a lot of time to start and stop. You have several choices, the quickest is to set TimeoutSec=0 in systemd and see how it will behaves in restarts, don't forget to not run your workaround ;-) More accurate solution is to execute directly start.sh and record how much time it needs to start and shutdown and after that tweak timeout values in systemd. If you are wondering how to stop openHAB while you are at the console - type "stop 0".

[Konstantin Polychronov]

Hi,
thanks a lot for your reply. This explains it all now. I've tested both scenarios and when I do the manual start/shutdown via the shell script the ports got unexported so it's definitely not a bug.

I'll look into systemd to check why it kills the process without waiting (tried the timeout=0 but for some reason didn't work). That's the easier part. :)

Thanks again !
Cheers,
K.

[Anthony Chan]

Hi guys,

Since this has to do with GPIO Im hoping someone could help me. I've finally just got done setting up OpenHab after a grueling few days of reading endless tutorials. I have a simple LED connected with resistor to GPIO 22.. I am able to turn on/off the light manually through command line. I unexport and run Openhab (have the GPIO specified in items file also) but when I switch on/off it doesn't work.  I am not seeing the GPIO file loaded on startup. Hopefully my startup output would help. I'd appreciate ANY help you guys can provide:

pi@raspberrypi /opt/openhab $ sudo ./start.sh
Launching the openHAB runtime...
osgi> 19:27:08.969 INFO  o.o.c.internal.CoreActivator[:61] - openHAB runtime has been started (v1.5.1).
19:27:34.716 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'exec.persist'
19:27:38.031 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'logging.persist'
19:27:39.317 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'db4o.persist'
19:27:39.594 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'rrd4j.persist'
19:27:40.654 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'demo.items'
19:27:56.476 INFO  o.o.i.s.i.DiscoveryServiceImpl[:72] - mDNS service has been started
19:28:04.955 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'demo.sitemap'
19:28:11.967 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'demo.script'
19:28:21.317 INFO  o.o.io.rest.RESTApplication[:143] - Started REST API at /rest
19:28:27.779 INFO  o.o.u.w.i.s.WebAppServlet[:79] - Started Classic UI at /openhab.app
19:28:35.445 INFO  o.o.m.c.i.ModelRepositoryImpl[:79] - Loading model 'demo.rules'
19:29:04.575 ERROR o.o.m.r.i.engine.RuleEngine[:267] - Error during the execution of startup rule 'Initialize light states': Could not invoke method: org.openhab.model.script.actions.BusEvent.postUpdate(org.openhab.core.items.Item,java.lang.Number) on instance: null
19:29:10.670 ERROR o.o.m.r.i.engine.RuleEngine[:267] - Error during the execution of startup rule 'Initialize heating states': Could not invoke method: org.openhab.model.script.actions.BusEvent.postUpdate(org.openhab.core.items.Item,java.lang.Number) on instance: null
19:29:13.842 ERROR o.o.m.r.i.engine.RuleEngine[:267] - Error during the execution of startup rule 'Initialize contact states': Could not invoke method: org.openhab.model.script.actions.BusEvent.postUpdate(org.openhab.core.items.Item,java.lang.Number) on instance: null
19:29:20.280 WARN  o.o.c.p.e.PersistenceExtensions[:404] - There is no queryable persistence service registered with the name 'rrd4j'
19:29:20.305 ERROR o.o.m.r.i.engine.RuleEngine[:267] - Error during the execution of startup rule 'Update max and min temperatures': cannot invoke method public abstract org.openhab.core.types.State org.openhab.core.persistence.HistoricItem.getState() on null
19:29:20.541 INFO  o.o.c.s.AbstractActiveService[:169] - Exec Refresh Service has been started
19:29:20.600 INFO  runtime.busevents[:26] - Temperature_GF_Corridor state updated to 20.80000000
19:29:20.736 INFO  runtime.busevents[:26] - Temperature_GF_Toilet state updated to 21.00000000
19:29:20.766 INFO  runtime.busevents[:26] - Temperature_GF_Living state updated to 20.40000000
19:29:20.798 INFO  runtime.busevents[:26] - Temperature_GF_Kitchen state updated to 20.70000000
19:29:20.838 INFO  runtime.busevents[:26] - Temperature_FF_Bath state updated to 20.10000000
19:29:20.883 INFO  runtime.busevents[:26] - Temperature_FF_Office state updated to 20.80000000
19:29:20.917 INFO  runtime.busevents[:26] - Temperature_FF_Child state updated to 22.00000000
19:29:20.947 INFO  runtime.busevents[:26] - Temperature_FF_Bed state updated to 20.10000000
19:29:21.928 WARN  o.o.c.p.e.PersistenceExtensions[:404] - There is no queryable persistence service registered with the name 'rrd4j'
19:29:21.947 WARN  o.o.c.p.e.PersistenceExtensions[:130] - There is no queryable persistence service registered with the name 'rrd4j'
19:30:00.100 WARN  o.o.c.p.e.PersistenceExtensions[:404] - There is no queryable persistence service registered with the name 'rrd4j'
19:30:00.133 WARN  o.o.c.p.e.PersistenceExtensions[:130] - There is no queryable persistence service registered with the name 'rrd4j'
19:30:00.298 INFO  runtime.busevents[:26] - Temperature_GF_Corridor state updated to 18.10000000
19:30:00.375 INFO  runtime.busevents[:26] - Temperature_GF_Toilet state updated to 21.60000000
19:30:00.473 INFO  runtime.busevents[:26] - Temperature_GF_Living state updated to 17.80000000
19:30:00.547 INFO  runtime.busevents[:26] - Temperature_GF_Kitchen state updated to 21.30000000
19:30:00.638 INFO  runtime.busevents[:26] - Temperature_FF_Bath state updated to 18.30000000
19:30:00.700 INFO  runtime.busevents[:26] - Temperature_FF_Office state updated to 20.20000000
19:30:00.764 INFO  runtime.busevents[:26] - Temperature_FF_Child state updated to 18.10000000
19:30:00.868 INFO  runtime.busevents[:26] - Temperature_FF_Bed state updated to 19.70000000
19:31:00.068 WARN  o.o.c.p.e.PersistenceExtensions[:404] - There is no queryable persistence service registered with the name 'rrd4j'
19:31:00.077 WARN  o.o.c.p.e.PersistenceExtensions[:130] - There is no queryable persistence service registered with the name 'rrd4j'
19:32:00.054 WARN  o.o.c.p.e.PersistenceExtensions[:404] - There is no queryable persistence service registered with the name 'rrd4j'
19:32:00.063 WARN  o.o.c.p.e.PersistenceExtensions[:130] - There is no queryable persistence service registered with the name 'rrd4j'
19:32:29.183 WARN  o.o.c.t.i.s.MapTransformationService[:70] - Could not find a mapping for '-' in the file 'en.map'.
19:32:31.949 INFO  runtime.busevents[:22] - Light_GF_Kitchen_Ceiling received command ON
19:32:32.707 WARN  o.o.c.t.i.s.MapTransformationService[:70] - Could not find a mapping for '-' in the file 'en.map'.
19:33:00.048 WARN  o.o.c.p.e.PersistenceExtensions[:404] - There is no queryable persistence service registered with the name 'rrd4j'
19:33:00.057 WARN  o.o.c.p.e.PersistenceExtensions[:130] - There is no queryable persistence service registered with the name 'rrd4j'
19:34:00.076 WARN  o.o.c.p.e.PersistenceExtensions[:404] - There is no queryable persistence service registered with the name 'rrd4j'
19:34:00.086 WARN  o.o.c.p.e.PersistenceExtensions[:130] - There is no queryable persistence service registered with the name 'rrd4j'
19:35:00.098 WARN  o.o.c.p.e.PersistenceExtensions[:404] - There is no queryable persistence service registered with the name 'rrd4j'
19:35:00.132 WARN  o.o.c.p.e.PersistenceExtensions[:130] - There is no queryable persistence service registered with the name 'rrd4j'
19:35:00.277 INFO  runtime.busevents[:26] - Temperature_GF_Corridor state updated to 19.50000000
19:35:00.349 INFO  runtime.busevents[:26] - Temperature_GF_Toilet state updated to 17.70000000
19:35:00.406 INFO  runtime.busevents[:26] - Temperature_GF_Living state updated to 18.10000000
19:35:00.463 INFO  runtime.busevents[:26] - Temperature_GF_Kitchen state updated to 19.30000000
19:35:00.523 INFO  runtime.busevents[:26] - Temperature_FF_Bath state updated to 18.70000000
19:35:00.607 INFO  runtime.busevents[:26] - Temperature_FF_Office state updated to 21.10000000
19:35:00.703 INFO  runtime.busevents[:26] - Temperature_FF_Child state updated to 19.80000000
19:35:00.805 INFO  runtime.busevents[:26] - Temperature_FF_Bed state updated to 22.50000000
19:35:00.771 WARN  o.o.c.t.i.s.MapTransformationService[:70] - Could not find a mapping for '-' in the file 'en.map'.
19:36:00.050 WARN  o.o.c.p.e.PersistenceExtensions[:404] - There is no queryable persistence service registered with the name 'rrd4j'
19:36:00.552 WARN  o.o.c.p.e.PersistenceExtensions[:130] - There is no queryable persistence service registered with the name 'rrd4j'
19:37:00.081 WARN  o.o.c.p.e.PersistenceExtensions[:404] - There is no queryable persistence service registered with the name 'rrd4j'
19:37:00.098 WARN  o.o.c.p.e.PersistenceExtensions[:130] - There i

[Anthony Chan]

Here's what I am seeing in my logs. I cannot seem to get this simple LED to light via openhab but it lights via command line with no issues.

21:17:06.985 ERROR o.o.m.c.i.f.FolderObserver[:105] - An unexpected exception has occured
java.lang.NullPointerException: null
    at org.openhab.binding.gpio.internal.GPIOGenericBindingProvider.processBindingConfiguration(GPIOGenericBindingProvider.java:89)
21:17:13.869 WARN  o.o.c.t.i.s.MapTransformationService[:70] - Could not find a mapping for '-' in the file 'en.map'.
21:17:17.399 INFO  runtime.busevents[:22] - Light_GF_Kitchen_Table received command ON
21:17:17.018 INFO  o.o.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.items'
21:17:18.716 INFO  runtime.busevents[:26] - Light_GF_Living_Table state updated to Undefined
21:17:18.810 ERROR o.o.m.c.i.f.FolderObserver[:105] - An unexpected exception has occured
java.lang.NullPointerException: null
    at org.openhab.binding.gpio.internal.GPIOGenericBindingProvider.processBindingConfiguration(GPIOGenericBindingProvider.java:89)

[Anthony Chan]

    at org.openhab.binding.gpio.internal.GPIOGenericBindingProvider.processBindingConfiguration(GPIOGenericBindingProvider.java:89)
22:47:29.626 WARN  o.o.c.t.i.s.MapTransformationService[:70] - Could not find a mapping for '-' in the file 'en.map'.
22:47:31.961 INFO  runtime.busevents[:22] - Light_GF_Living_Table received command OFF
22:47:32.495 WARN  o.o.c.t.i.s.MapTransformationService[:70] - Could not find a mapping for '-' in the file 'en.map'.
22:47:38.353 INFO  o.o.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.items'
22:47:40.039 INFO  runtime.busevents[:26] - Light_GF_Living_Table state updated to Undefined
22:47:40.123 ERROR o.o.m.c.i.f.FolderObserver[:105] - An unexpected exception has occured

java.lang.NullPointerException: null
    at org.openhab.binding.gpio.internal.GPIOGenericBindingProvider.processBindingConfiguration(GPIOGenericBindingProvider.java:89)

22:47:40.182 WARN  o.o.c.t.i.s.MapTransformationService[:70] - Could not find a mapping for '-' in the file 'en.map'.
    22:47:50.184 INFO  o.o.m.c.i.ModelRepositoryImpl[:97] - Refreshing model 'demo.items'
22:47:50.445 INFO  runtime.busevents[:26] - Light_GF_Living_Table state updated to Undefined
22:47:50.477 ERROR o.o.m.c.i.f.FolderObserver[:105] - An unexpected exception has occured