Connection pooling in modbus binding

ssalonen · March 8, 2016, 7:05pm

Hi @mbs38! Can you please paste you logback_debug.xml configuration? I’m still missing some log statements.

mbs38 · March 8, 2016, 7:08pm

Done. I think there is something peculiar going on here:

With this configuration: conf - Pastebin.com
Performance, start.sh: 1864, logs: no errors
Performance, start_debug.sh: 1864 logs: 19:29:39.915 [TRACE] [dbusSlaveConnectionFactoryImpl:108 ] - Waited 0ms (interB - Pastebin.com

With this configuration: modbus:poll=5#agsBus-Mastermodbus:serial.agsBusMasterHolding.connection=/dev - Pastebin.com
Performance, start.sh: 240 (!), logs: nondebug - Pastebin.com
Performance, start_debug.sh: 1870 (!) logs: 19:36:53.667 [TRACE] [dbusSlaveConnectionFactoryImpl:135 ] - Validating endpoin - Pastebin.com

How can we debug something that does work once you start debugging… -.-

logback_debug.xml: <configuration scan="true"> <appender name="STDOUT" class="ch.qos.logback.co - Pastebin.com
logback.xml: <configuration scan="true"> <appender name="STDOUT" class="ch.qos.logback.co - Pastebin.com

Best regards,
M

ssalonen · March 8, 2016, 8:11pm

Thank you so much @mbs38!

fixing logging

Regarding your logging configuration, can you please remove multiple definitions for the same logger. Now you have:

    <logger name="net.wimpi.modbus" level="DEBUG" />
    <logger name="net.wimpi.modbus" level="TRACE" />
    <logger name="net.wimpi.modbus" level="INFO" />

Leave just the TRACE:

    <logger name="net.wimpi.modbus" level="TRACE" />

This explain the missing log statements.

why debug and non-debug are different

(everything is a theory of course… unless proven otherwise )

Indeed, that feels weird but I believe the explanation is still the natural one: the delay introduced by all the logging makes the duration between transactions larger which again reduces the errors we get with the serial device. The difference between “non-debug” and “debug” configurations vanishes when the inter transaction delay is increased from the 10ms since then the modbus binding waits couple of milliseconds to ensure enough delay between transactions. It should be highlighted that the inter transaction delay does nothing if enough time has passed since the transaction – it only waits if previous transaction was just executed. Perhaps I should consider renaming the parameter…

As mentioned in the summary, best performance you got out with a single slave was ~24ms/transaction – even though the inter transaction delay parameter was set to 10ms. This means that due to read/write taking time, roughly 14ms goes just to that. In fact, some sort ideal performance was witnessed in my “virtual null modem” test, where IO took basically all the time (11ms to read modbus response, ~1ms to overhead in the binding to facilitiate next transactions).

Still, it beats to me why multiple slaves has different performance and different issues than single slave configuration – even though the time between transactions is the same (for example, 25ms). This is why I asked you to clarify the devices you are serving behind /dev/ttyS0. If the devices are different, the multi-slave might not be comparable with single-slave test.

Let me suggest next steps

1. please run single slave configuration with logging fixed (see above). Use this configuration:

modbus:poll=5
modbus:serial.slave1.connection=/dev/ttyS0:38400:8:none:1:rtu:280:35
modbus:serial.slave1.id=247
modbus:serial.slave1.start=42
modbus:serial.slave1.length=14
modbus:serial.slave1.type=holding

Do not have any rules in openhab. Have this item only, nothing else:

Number Slave1Item1 "slave1 (modbus) [%d]" {modbus="slave1:0"}

2. please run multiple slave configuration, with logging fixed, repeating same slave definition with different names

Use this configuration (13 identical slaves with 35ms inter transaction delay). Do not have any rules. Have these items only, nothing else:

Number Slave1Item1 "slave1 (modbus) [%d]" {modbus="slave1:0"}
Number Slave2Item1 "slave2 (modbus) [%d]" {modbus="slave2:0"}
Number Slave3Item1 "slave3 (modbus) [%d]" {modbus="slave3:0"}
Number Slave4Item1 "slave4 (modbus) [%d]" {modbus="slave4:0"}
Number Slave5Item1 "slave5 (modbus) [%d]" {modbus="slave5:0"}
Number Slave6Item1 "slave6 (modbus) [%d]" {modbus="slave6:0"}
Number Slave7Item1 "slave7 (modbus) [%d]" {modbus="slave7:0"}
Number Slave8Item1 "slave8 (modbus) [%d]" {modbus="slave8:0"}
Number Slave9Item1 "slave9 (modbus) [%d]" {modbus="slave9:0"}
Number Slave10Item1 "slave10 (modbus) [%d]" {modbus="slave10:0"}
Number Slave11Item1 "slave11 (modbus) [%d]" {modbus="slave11:0"}
Number Slave12Item1 "slave12 (modbus) [%d]" {modbus="slave12:0"}
Number Slave13Item1 "slave13 (modbus) [%d]" {modbus="slave13:0"}

In both cases, it is enough to store debug level logs only. Please let it run for 10secs at least so
we get good picture of the performance.

For the tests it is important that the slave definitions are identical in both single-slave and multi-slave configurations. This should make situations more comparable.

If you please do these steps we should have much much better understanding what is going on.

mbs38 · March 9, 2016, 9:53am

@ssalonen here are the logs:

I’ve copied the configuration that you suggested. No rules, a single item.

Single slave: http://pastebin.com/jLS66CtQ
Multiple slaves: coming soon…

ssalonen · March 9, 2016, 10:22am

@mbs38 Please keep the TRACE level org.openhab.binding.modbus log statements as well. Sorry for my unclear messaging!

mbs38 · March 9, 2016, 10:40am

@ssalonen

Like this
logger name=“org.openhab.binding.modbus” level="TRACE"
logger name=“net.wimpi.modbus” level=“TRACE”
?

mbs38 · March 9, 2016, 11:53am

@ssalonen

I accidently doubled one item, but that doesn’t seem to have any effect.

start_debug:
single: http://pastebin.com/xzvfvVhq
multiple: http://pastebin.com/XWNt2D5A

Performance was good with single (1868) and okay with multiple (1499) although significantly lower.

Now for the record the bad part:
start:
single: http://pastebin.com/Wvs5Ba4d (just state updates, performance is okay (1498))
multiple: http://pastebin.com/brid9TWf (tons of errors, crappy performance (~400))

ssalonen · March 9, 2016, 5:13pm

@mbs38 Thank you for running the tests. I have problems following the logs now that the item names are different.

Could you please repeat with items exactly as above, so it’s easier to follow and compare different runs.

mbs38 · March 9, 2016, 6:52pm

Simply ignore the state update messages of slave1h12.

slave1h12 and Slave1Item1 point to the same modbus register.

ssalonen · March 15, 2016, 10:04pm

Thanks for the logs.

Before opening up details on the logs, could you confirm that inter transaction delay of 35ms was also used for the “start” runs? I ask because I see state updates with shorter interval too…

Best,
Sami

mbs38 · March 15, 2016, 10:57pm

Yes it was. I haven’t changed the configuration in any way. Just ran start.sh instead of start_debug.sh.

Best regards,
Max

ssalonen · March 16, 2016, 6:29am

@mbs38 OK, that is weird.

Thank you very much from the logs, they were really useful. To keep things short I’m going to actual next fix suggestion.

I have a new lead now from the logs and have changed the interpretation of inter transaction delay. Now it ensures that certain time passes between end of previous transaction and the start of the next one. Previously time between “transaction starts” was measured. From the logs I noticed that at least in your case the time it takes to read the response varies, which makes the inter transaction delay a bit “non-deterministic”.

Can you try again with the same configs this new version? Configuration format should be the same.

I truly appreciate your help testing this.

mbs38 · March 16, 2016, 3:57pm

It works! My productive system now achieves 1732 updates a minute in non-debug mode. Just for the record the configuration I’m using now is:

modbus:poll=5

And like this for 13 different slave IDs:
modbus:serial.someSlave.connection=/dev/ttyS0:38400:8:none:1:rtu:280:3

No errors, just literally thousands of state updates

I haven’t tried debug mode yet.
Just wanted to let you know as quickly as possible. Great work. Thanks a lot!

Best regards,
Max

ssalonen · March 16, 2016, 6:55pm

Oh this is so great to hear!!

Keep me posted how it works out. Also, if you test writing commands as well, I would appreciate it very much.

I think I’m going to change the order of readTimeout (e.g. 280) and inter transaction delay (e.g. 3ms) to allow overriding the most typical parameters. What do you think should be the default for inter transaction delay, probably we want something that works for most of the users out-of-the-box. We can always document in the wiki “tuning tips” for the high-performance users like you. How about 50ms?

ssalonen · March 16, 2016, 6:58pm

@YMedox @Ferryb4 Do you mind testing the v6 version also?

I would like to have modbus TCP tested as well by multiple people before starting to prepare for the pull request to official modbus binding.

Ferryb4 · March 16, 2016, 8:35pm

Hi ssalonen,

I have no errors or issues.
I did a poll of 1000 with 16 slaves

It seems that all problems are solved.

Great work

LeXLuther422 · March 17, 2016, 1:25pm

I’m running 1.81 and it doesn’t seem to poll devices. It was running fine under the 1.8.0 Snapshot.
I only added the :100 to the end of each line. It defines the items then it instances slave1 then stops doing anything else with modbus

#modbus:poll=1000
modbus:poll=5

modbus:tcp.slave1.connection=192.168.1.200:502:rtu:100
modbus:tcp.slave1.type=holding
modbus:tcp.slave1.start=39
modbus:tcp.slave1.length=1
#modbus:tcp.slave1.valuetype=uint16

#ADAM 6060 12-Channel Digital I/O Module
modbus:tcp.slave2.connection=192.168.1.106:502:100
modbus:tcp.slave2.type=coil
modbus:tcp.slave2.start=16
modbus:tcp.slave2.length=6
modbus:tcp.slave2.valuetype=bit
modbus:tcp.slave3.connection=192.168.1.106:502:100
modbus:tcp.slave3.type=discrete
modbus:tcp.slave3.start=0
modbus:tcp.slave3.length=5
modbus:tcp.slave3.valuetype=bit
modbus:tcp.slave5.connection=192.168.1.106:502:100
modbus:tcp.slave5.type=input
modbus:tcp.slave5.start=10
modbus:tcp.slave5.length=2
modbus:tcp.slave5.valuetype=float32


#ADAM 6024 12-Channel Universal I/O Module
modbus:tcp.slave4.connection=192.168.1.105:502:100
modbus:tcp.slave4.type=input
modbus:tcp.slave4.start=0
modbus:tcp.slave4.length=6

#Watlow F4
modbus:tcp.slave6.connection=192.168.1.104:502:100
modbus:tcp.slave6.type=input
modbus:tcp.slave6.start=100
modbus:tcp.slave6.length=16
modbus:tcp.slave7.connection=192.168.1.104:502:100
modbus:tcp.slave7.type=input
modbus:tcp.slave7.start=200
modbus:tcp.slave7.length=64
modbus:tcp.slave8.connection=192.168.1.104:502:100
modbus:tcp.slave8.type=holding
modbus:tcp.slave8.start=300
modbus:tcp.slave8.length=64
modbus:tcp.slave9.connection=192.168.1.104:502:100
modbus:tcp.slave9.type=holding
modbus:tcp.slave9.start=2000
modbus:tcp.slave9.length=63

#Motor Control
modbus:tcp.slave10.connection=192.168.1.104:502:100
modbus:tcp.slave10.id=2
modbus:tcp.slave10.type=holding
modbus:tcp.slave10.start=0
modbus:tcp.slave10.length=25

ssalonen · March 17, 2016, 3:22pm

Thanks @LeXLuther422. OK, so something to fix still!

Can you paste your run with TRACE level logs

    <logger name="net.wimpi.modbus" level="TRACE" />
    <logger name="org.openhab.binding.modbus" level="TRACE" />

Thank you.

LeXLuther422 · March 17, 2016, 3:55pm

it the logback_debug.xml I have them set to trace.

Launching the openHAB runtime...
Listening for transport dt_socket at address: 8001
osgi> 10:49:55.543 [DEBUG] [.s.internal.SchedulerActivator:36   ] - Scheduler has been started.
10:49:55.590 [INFO ] [uartz.impl.StdSchedulerFactory:1175 ] - Using default implementation for ThreadExecutor
10:49:55.621 [INFO ] [rtz.core.SchedulerSignalerImpl:61   ] - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
10:49:55.621 [INFO ] [rg.quartz.core.QuartzScheduler:243  ] - Quartz Scheduler v.2.1.7 created.
10:49:55.621 [INFO ] [org.quartz.simpl.RAMJobStore  :154  ] - RAMJobStore initialized.
10:49:55.621 [INFO ] [rg.quartz.core.QuartzScheduler:268  ] - Scheduler meta-data: Quartz Scheduler (v2.1.7) 'openHAB-job-scheduler' with instanceId 'NON_CLUSTERED'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 2 threads.
  Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.

10:49:55.621 [INFO ] [uartz.impl.StdSchedulerFactory:1324 ] - Quartz scheduler 'openHAB-job-scheduler' initialized from specified file: './etc/quartz.properties'
10:49:55.621 [INFO ] [uartz.impl.StdSchedulerFactory:1328 ] - Quartz scheduler version: 2.1.7
10:49:55.621 [INFO ] [rg.quartz.core.QuartzScheduler:534  ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
10:49:55.621 [DEBUG] [o.config.core.ConfigDispatcher:146  ] - Processing openHAB default configuration file 'C:\OpenHAB\configurations\openhab_default.cfg'.
10:49:55.668 [DEBUG] [o.config.core.ConfigDispatcher:168  ] - Processing openHAB main configuration file 'C:\OpenHAB\configurations\openhab.cfg'.
10:49:55.699 [DEBUG] [.o.core.internal.CoreActivator:93   ] - UUID file already exists at 'C:\OpenHAB\webapps\static\uuid' with content '02d9bcdf-6869-48f3-93a3-c8b7cb27f07e'
10:49:55.699 [DEBUG] [.o.core.internal.CoreActivator:115  ] - Created file 'C:\OpenHAB\webapps\static\version' with content '1.8.1'
10:49:55.699 [INFO ] [.o.core.internal.CoreActivator:61   ] - openHAB runtime has been started (v1.8.1).
10:49:55.730 [DEBUG] [a.internal.AutoUpdateActivator:31   ] - AutoUpdate binding has been started.
10:49:56.855 [DEBUG] [.p.i.PersistenceModelActivator:23   ] - Registered 'persistence' configuration parser
10:49:56.871 [DEBUG] [.c.t.i.TransformationActivator:38   ] - Transformation Service has been started.
10:49:56.902 [DEBUG] [m.internal.MultimediaActivator:34   ] - Multimedia I/O bundle has been started.
10:49:56.918 [DEBUG] [.s.i.DiscoveryServiceActivator:27   ] - Discovery service has been started.
10:49:56.918 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl:93   ] - mDNS service has been started
10:49:56.949 [DEBUG] [.io.transport.mqtt.MqttService:123  ] - Starting MQTT Service...
10:49:57.043 [DEBUG] [.i.internal.ItemModelActivator:24   ] - Registered 'item' configuration parser
10:49:57.184 [DEBUG] [o.o.c.i.items.ItemRegistryImpl:137  ] - Item provider 'GenericItemProvider' has been added.
10:49:57.574 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl:53   ] - Service Discovery initialization completed.
10:49:57.746 [INFO ] [.io.transport.mqtt.MqttService:108  ] - MQTT Service initialization completed.
10:49:57.746 [INFO ] [o.i.t.m.i.MqttBrokerConnection:114  ] - Starting MQTT broker connection 'xtralight'
10:49:57.746 [DEBUG] [o.i.t.m.i.MqttBrokerConnection:294  ] - Creating new client for 'tcp://localhost:1883' using id 'OpenHAB' and file store 'C:\DOCUME~1\DAVID~1.LUT\LOCALS~1\Tem
p\1\/xtralight'
10:49:57.965 [DEBUG] [.o.m.s.i.SitemapModelActivator:23   ] - Registered 'sitemap' configuration parser
10:49:58.043 [DEBUG] [io.rest.internal.RESTActivator:33   ] - REST API has been started.
10:49:58.106 [INFO ] [org.atmosphere.util.IOUtils   :370  ] - META-INF/services/org.atmosphere.cpr.AtmosphereFramework not found in class loader
10:49:58.137 [INFO ] [sphere.cpr.AtmosphereFramework:2601 ] - Atmosphere is using org.atmosphere.cpr.DefaultAnnotationProcessor for processing annotation
10:49:58.137 [INFO ] [cpr.DefaultAnnotationProcessor:138  ] - AnnotationProcessor class org.atmosphere.cpr.DefaultAnnotationProcessor$BytecodeBasedAnnotationProcessor being used
10:49:58.168 [WARN ] [cpr.DefaultAnnotationProcessor:178  ] - Unable to detect annotations. Application may fail to deploy.
10:49:58.184 [INFO ] [sphere.cpr.AtmosphereFramework:1891 ] - Auto detecting atmosphere handlers /WEB-INF/classes/
10:49:58.199 [INFO ] [sphere.cpr.AtmosphereFramework:639  ] - Installed AtmosphereHandler org.atmosphere.handler.ReflectorServletProcessor mapped to context-path /* and Broadcaster
 Class org.atmosphere.jersey.JerseyBroadcaster
10:49:58.199 [INFO ] [sphere.cpr.AtmosphereFramework:1945 ] - Auto detecting WebSocketHandler in /WEB-INF/classes/
10:49:58.199 [INFO ] [sphere.cpr.AtmosphereFramework:1602 ] - Installed WebSocketProtocol org.atmosphere.websocket.protocol.SimpleHttpProtocol
10:49:58.231 [INFO ] [.a.h.ReflectorServletProcessor:103  ] - Installing Servlet com.sun.jersey.spi.container.servlet.ServletContainer
10:49:58.356 [INFO ] [c.s.j.s.i.a.WebApplicationImpl:815  ] - Initiating Jersey application, version 'Jersey: 1.18.1 02/19/2014 03:28 AM'
10:49:58.356 [INFO ] [c.s.j.s.i.a.WebApplicationImpl:826  ] - Adding the following classes declared in META-INF/services/jersey-server-components to the resource configuration:
  class org.atmosphere.jersey.AtmosphereResourceConfigurator
10:49:58.418 [INFO ] [j.s.i.a.DeferredResourceConfig:101  ] - Instantiated the Application class org.openhab.io.rest.RESTApplication
10:49:59.293 [INFO ] [sphere.cpr.AtmosphereFramework:2435 ] - AtmosphereInterceptor CORS Interceptor Support will always be executed first
10:49:59.293 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor CORS Interceptor Support with priority FIRST_BEFORE_DEFAULT
10:49:59.293 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Default Response's Headers Interceptor with priority AFTER_DEFAULT
10:49:59.293 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Android Interceptor Support with priority AFTER_DEFAULT
10:49:59.293 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor SSE Interceptor Support with priority AFTER_DEFAULT
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor JSONP Interceptor Support with priority AFTER_DEFAULT
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Atmosphere JavaScript Protocol with priority AFTER_DEFAULT
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Browser disconnection detection with priority AFTER_DEFAULT
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:935  ] - Using EndpointMapper class org.atmosphere.util.DefaultEndpointMapper
10:49:59.309 [WARN ] [sphere.cpr.AtmosphereFramework:941  ] - No BroadcasterCache configured. Broadcasted message between client reconnection will be LOST. It is recommended to con
figure the org.atmosphere.cache.UUIDBroadcasterCache
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:949  ] - Default Broadcaster Class: org.atmosphere.jersey.JerseyBroadcaster
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:950  ] - Broadcaster Polling Wait Time 100
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:951  ] - Shared ExecutorService supported: true
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:958  ] - Messaging Thread Pool Size: 10
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:968  ] - Async I/O Thread Pool Size: 10
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:979  ] - Using BroadcasterFactory: org.atmosphere.cpr.DefaultBroadcasterFactory
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:980  ] - Using WebSocketProcessor: org.atmosphere.websocket.DefaultWebSocketProcessor
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:990  ] - Invoke AtmosphereInterceptor on WebSocket message true
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:991  ] - HttpSession supported: false
10:49:59.309 [INFO ] [sphere.cpr.AtmosphereFramework:993  ] - Atmosphere is using DefaultAtmosphereObjectFactory for dependency injection and object creation
10:49:59.324 [INFO ] [sphere.cpr.AtmosphereFramework:994  ] - Atmosphere is using async support: org.atmosphere.container.JettyAsyncSupportWithWebSocket running under container: je
tty/8.1.3.v20120522 with WebSocket enabled.
10:49:59.324 [INFO ] [sphere.cpr.AtmosphereFramework:996  ] - Atmosphere Framework 2.2.5 started.
10:49:59.324 [INFO ] [sphere.cpr.AtmosphereFramework:998  ] -

        For Atmosphere Framework Commercial Support, visit
        http://www.async-io.org/ or send an email to support@async-io.org

10:49:59.324 [INFO ] [penhab.io.rest.RESTApplication:144  ] - Started REST API at /rest
10:49:59.324 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:66   ] - Registering new service _openhab-server._tcp.local. at port 8080
10:49:59.340 [ERROR] [.io.transport.mqtt.MqttService:114  ] - Error starting broker connection
org.eclipse.paho.client.mqttv3.MqttException: Unable to connect to server
        at org.eclipse.paho.client.mqttv3.internal.TCPNetworkModule.start(TCPNetworkModule.java:75) ~[na:na]
        at org.eclipse.paho.client.mqttv3.internal.ClientComms$ConnectBG.run(ClientComms.java:538) ~[na:na]
        at java.lang.Thread.run(Unknown Source) ~[na:1.8.0_66]
Caused by: java.net.ConnectException: Connection refused: connect
        at java.net.TwoStacksPlainSocketImpl.socketConnect(Native Method) ~[na:1.8.0_66]
        at java.net.AbstractPlainSocketImpl.doConnect(Unknown Source) ~[na:1.8.0_66]
        at java.net.AbstractPlainSocketImpl.connectToAddress(Unknown Source) ~[na:1.8.0_66]
        at java.net.AbstractPlainSocketImpl.connect(Unknown Source) ~[na:1.8.0_66]
        at java.net.PlainSocketImpl.connect(Unknown Source) ~[na:1.8.0_66]
        at java.net.SocksSocketImpl.connect(Unknown Source) ~[na:1.8.0_66]
        at java.net.Socket.connect(Unknown Source) ~[na:1.8.0_66]
        at org.eclipse.paho.client.mqttv3.internal.TCPNetworkModule.start(TCPNetworkModule.java:66) ~[na:na]
        ... 2 common frames omitted
10:50:05.231 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:66   ] - Registering new service _openhab-server-ssl._tcp.local. at port 8443
10:50:06.575 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'atal.sitemap'
10:50:06.825 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'default.sitemap'
10:50:06.872 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'db4o.persist'
10:50:06.903 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'exec.persist'
10:50:06.903 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'logging.persist'
10:50:06.903 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'rrd4j.persist'
10:50:06.950 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'demo.script'
10:50:07.122 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'camera.items'
10:50:07.137 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'camera.items'
10:50:07.137 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'camera.items'
10:50:07.153 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'Compressor.items'
10:50:07.153 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'Compressor.items'
10:50:07.153 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'camera.items'
10:50:07.153 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'Compressor.items'
10:50:07.169 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'demo.items'
10:50:07.184 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'demo.items'
10:50:07.184 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'camera.items'
10:50:07.184 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'Compressor.items'
10:50:07.184 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'demo.items'
10:50:07.184 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'EVChamber.items'
10:50:07.200 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'EVChamber.items'
10:50:07.200 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'camera.items'
10:50:07.200 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'Compressor.items'
10:50:07.200 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'demo.items'
10:50:07.200 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'EVChamber.items'
10:50:07.200 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'MQTT.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'MQTT.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'camera.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'Compressor.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'demo.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'EVChamber.items'
10:50:07.216 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'MQTT.items'
10:50:07.231 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'test.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'test.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'camera.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'Compressor.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'demo.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'EVChamber.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'MQTT.items'
10:50:07.231 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'test.items'
10:50:08.075 [INFO ] [.o.u.w.i.servlet.WebAppServlet:80   ] - Started Classic UI at /classicui/openhab.app
10:50:08.356 [DEBUG] [.r.internal.RuleModelActivator:42   ] - Registered 'rules' configuration parser
10:50:08.372 [DEBUG] [m.r.internal.engine.RuleEngine:77   ] - Started rule engine
10:50:10.700 [DEBUG] [.a.mail.internal.MailActivator:34   ] - Mail action has been started.
10:50:10.700 [DEBUG] [o.o.b.w.i.bus.WeatherActivator:32   ] - Weather binding has been started.
10:50:10.763 [DEBUG] [.w.internal.gfx.WeatherServlet:62   ] - Starting up weather servlet at /weather
10:50:10.778 [DEBUG] [.rrd4j.internal.RRD4jActivator:31   ] - RRD4j persistence bundle has been started.
10:50:10.794 [WARN ] [.p.rrd4j.internal.RRD4jService:389  ] - Unknown property name : org.openhab.persistence.rrd4j
10:50:10.794 [DEBUG] [.p.rrd4j.internal.RRD4jService:358  ] - config 'objectClass' should have the format 'name.configkey'
10:50:10.794 [INFO ] [.p.rrd4j.internal.RRD4jService:401  ] - Removing invalid defintion component = null heartbeat = 0 min/max = 0.0/0.0 step = 0 0 archives(s) = [] 0 items(s) = [
]
10:50:10.794 [DEBUG] [.p.rrd4j.internal.RRD4jService:399  ] - Created default_other = GAUGE heartbeat = 3600 min/max = NaN/NaN step = 1 6 archives(s) = [ MAX xff = 0.999 steps = 1
rows = 3600 MAX xff = 0.999 steps = 10 rows = 1440 MAX xff = 0.999 steps = 60 rows = 1440 MAX xff = 0.999 steps = 900 rows = 2880 MAX xff = 0.999 steps = 21600 rows = 1460 MAX xff
= 0.999 steps = 86400 rows = 3650] 0 items(s) = []
10:50:10.794 [DEBUG] [.p.rrd4j.internal.RRD4jService:399  ] - Created default_numeric = GAUGE heartbeat = 60 min/max = NaN/NaN step = 60 6 archives(s) = [ AVERAGE xff = 0.5 steps =
 1 rows = 480 AVERAGE xff = 0.5 steps = 4 rows = 360 AVERAGE xff = 0.5 steps = 14 rows = 644 AVERAGE xff = 0.5 steps = 60 rows = 720 AVERAGE xff = 0.5 steps = 720 rows = 730 AVERAG
E xff = 0.5 steps = 10080 rows = 520] 0 items(s) = []
10:50:10.809 [DEBUG] [.p.internal.PersistenceManager:146  ] - Initializing rrd4j persistence service.
10:50:10.825 [DEBUG] [.p.internal.PersistenceManager:328  ] - Item group 'Weather_Chart' does not exist.
10:50:10.825 [DEBUG] [.p.internal.PersistenceManager:328  ] - Item group 'toner' does not exist.
10:50:10.856 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Temperature_Serv2' -> '70.3400000000000034106051316484808
92181396484375'
10:50:10.856 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Humidity_Serv3' -> '49.2000000000000028421709430404007434
844970703125'
10:50:10.856 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Temperature_Serv1' -> '71.0600000000000022737367544323205
9478759765625'
10:50:10.856 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Humidity_Serv2' -> '61.2000000000000028421709430404007434
844970703125'
10:50:10.872 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'COMP_1_MAIN_Pressure_div' -> '110.34659399999999607189238
30427229404449462890625'
10:50:10.872 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Temperature_Serv3' -> '70.1599999999999965893948683515191
07818603515625'
10:50:10.872 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Humidity_Serv1' -> '58.3999999999999985789145284797996282
5775146484375'
10:50:10.872 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Chamber_TARGET_div' -> '0'
10:50:10.872 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'COMP_1_MAIN_Temp_div' -> '197.099999999999994315658113919
198513031005859375'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Chamber_TEMP1_div' -> '25.3999999999999985789145284797996
2825775146484375'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Chamber_SET1_div' -> '-40'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'AC_Circuit_Serv1' -> 'ON'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'AC_Circuit_Serv3' -> 'ON'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'AC_Circuit_Serv2' -> 'OFF'
10:50:10.888 [DEBUG] [.p.internal.PersistenceManager:377  ] - Restored item state from 'Mar 17, 2016 9:47:00 AM' for item 'Camera_11' -> 'ON'
10:50:10.903 [DEBUG] [.p.internal.PersistenceManager:428  ] - Scheduled strategy rrd4j.everyMinute with cron expression 0 * * * * ?
10:50:10.919 [DEBUG] [p.r.i.charts.RRD4jChartServlet:118  ] - Starting up rrd chart servlet at /rrdchart.png
10:50:10.934 [DEBUG] [xecPersistenceServiceActivator:33   ] - Exec persistence bundle has been started.
10:50:10.934 [DEBUG] [.p.internal.PersistenceManager:146  ] - Initializing exec persistence service.
10:50:10.934 [DEBUG] [.p.internal.PersistenceManager:428  ] - Scheduled strategy exec.everyMinute with cron expression 0 * * * * ?
10:50:10.934 [DEBUG] [.b.mqtt.internal.MqttActivator:34   ] - MQTT binding has been started.
10:50:10.950 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Humidity_Serv1 (Type=NumberItem, State=Uninitialized)' with 'MqttGener
icBindingProvider' reader.
10:50:10.950 [DEBUG] [b.mqtt.internal.MqttItemConfig:71   ] - Loaded MQTT config for item 'Humidity_Serv1' : 1 subscribers, 0 publishers
10:50:10.950 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Temperature_Serv1 (Type=NumberItem, State=Uninitialized)' with 'MqttGe
nericBindingProvider' reader.
10:50:10.950 [DEBUG] [b.mqtt.internal.MqttItemConfig:71   ] - Loaded MQTT config for item 'Temperature_Serv1' : 1 subscribers, 0 publishers
10:50:10.950 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'AC_Circuit_Serv1 (Type=SwitchItem, State=Uninitialized)' with 'MqttGen
ericBindingProvider' reader.
10:50:10.950 [DEBUG] [b.mqtt.internal.MqttItemConfig:71   ] - Loaded MQTT config for item 'AC_Circuit_Serv1' : 1 subscribers, 0 publishers
10:50:10.950 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Humidity_Serv2 (Type=NumberItem, State=Uninitialized)' with 'MqttGener
icBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71   ] - Loaded MQTT config for item 'Humidity_Serv2' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Temperature_Serv2 (Type=NumberItem, State=Uninitialized)' with 'MqttGe
nericBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71   ] - Loaded MQTT config for item 'Temperature_Serv2' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'AC_Circuit_Serv2 (Type=SwitchItem, State=Uninitialized)' with 'MqttGen
ericBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71   ] - Loaded MQTT config for item 'AC_Circuit_Serv2' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Door_Serv2 (Type=ContactItem, State=Uninitialized)' with 'MqttGenericB
indingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71   ] - Loaded MQTT config for item 'Door_Serv2' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Humidity_Serv3 (Type=NumberItem, State=Uninitialized)' with 'MqttGener
icBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71   ] - Loaded MQTT config for item 'Humidity_Serv3' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Temperature_Serv3 (Type=NumberItem, State=Uninitialized)' with 'MqttGe
nericBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71   ] - Loaded MQTT config for item 'Temperature_Serv3' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'AC_Circuit_Serv3 (Type=SwitchItem, State=Uninitialized)' with 'MqttGen
ericBindingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71   ] - Loaded MQTT config for item 'AC_Circuit_Serv3' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Door_Serv3 (Type=ContactItem, State=Uninitialized)' with 'MqttGenericB
indingProvider' reader.
10:50:10.966 [DEBUG] [b.mqtt.internal.MqttItemConfig:71   ] - Loaded MQTT config for item 'Door_Serv3' : 1 subscribers, 0 publishers
10:50:10.966 [DEBUG] [m.internal.MqttEventBusBinding:61   ] - MQTT: Activating event bus binding.
10:50:10.966 [DEBUG] [.o.b.ntp.internal.NtpActivator:31   ] - NTP binding has been started.
10:50:10.981 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Date (Type=DateTimeItem, State=Uninitialized)' with 'NtpGenericBinding
Provider' reader.
10:50:10.981 [INFO ] [.service.AbstractActiveService:169  ] - NTP Refresh Service has been started
10:50:10.997 [DEBUG] [.b.snmp.internal.SnmpActivator:35   ] - SNMP binding has been started.
10:50:11.028 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Camera_11 (Type=SwitchItem, State=Uninitialized)' with 'SnmpGenericBin
dingProvider' reader.
10:50:11.059 [DEBUG] [.o.b.snmp.internal.SnmpBinding:91   ] - SNMP binding activated
10:50:11.091 [DEBUG] [.o.b.snmp.internal.SnmpBinding:147  ] - SNMP binding is listening on 0.0.0.0/162
10:50:11.091 [INFO ] [.service.AbstractActiveService:169  ] - SNMP Refresh Service has been started
10:50:11.091 [DEBUG] [.o.b.snmp.internal.SnmpBinding:335  ] - Item 'Camera_11' is about to be refreshed
10:50:11.091 [DEBUG] [.o.b.snmp.internal.SnmpBinding:350  ] - SNMP: Send PDU 192.168.1.251/161 GET[requestID=0, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.2.2.1.8.41 = N
ull]]
10:50:11.106 [DEBUG] [.i.LoggingPersistenceActivator:31   ] - Logging persistence bundle has been started.
10:50:11.106 [DEBUG] [.p.internal.PersistenceManager:146  ] - Initializing logging persistence service.
10:50:11.122 [DEBUG] [o.b.m.internal.ModbusActivator:31   ] - Modbus binding has been started.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'COMP_1_MAIN_Temp (Type=NumberItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'lightstackred (Type=SwitchItem, State=Uninitialized)' with 'ModbusGene
ricBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'lightstackyellow (Type=SwitchItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'lightstackgreen (Type=SwitchItem, State=Uninitialized)' with 'ModbusGe
nericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'COMP_1_MAIN_Power (Type=SwitchItem, State=Uninitialized)' with 'Modbus
GenericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Fan1RPM_H (Type=NumberItem, State=Uninitialized)' with 'ModbusGenericB
indingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'COMP_1_MAIN_Pressure (Type=NumberItem, State=Uninitialized)' with 'Mod
busGenericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Chamber_SET1 (Type=NumberItem, State=Uninitialized)' with 'ModbusGener
icBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Chamber_TEMP1 (Type=NumberItem, State=Uninitialized)' with 'ModbusGene
ricBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Chamber_STAT1 (Type=NumberItem, State=Uninitialized)' with 'ModbusGene
ricBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Chamber_STAT_AL1 (Type=NumberItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
10:50:11.122 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Chamber_Heat (Type=NumberItem, State=Uninitialized)' with 'ModbusGener
icBindingProvider' reader.
10:50:11.138 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Chamber_STAT_AL2 (Type=NumberItem, State=Uninitialized)' with 'ModbusG
enericBindingProvider' reader.
10:50:11.138 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Chamber_COOL (Type=NumberItem, State=Uninitialized)' with 'ModbusGener
icBindingProvider' reader.
10:50:11.138 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Chamber_TARGET (Type=NumberItem, State=Uninitialized)' with 'ModbusGen
ericBindingProvider' reader.
10:50:11.138 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Chamber_Fan_Run (Type=NumberItem, State=Uninitialized)' with 'ModbusGe
nericBindingProvider' reader.
10:50:11.138 [DEBUG] [i.internal.GenericItemProvider:341  ] - Start processing binding configuration of Item 'Chamber_Fan_Speed (Type=NumberItem, State=Uninitialized)' with 'Modbus
GenericBindingProvider' reader.
10:50:11.169 [DEBUG] [.modbus.internal.ModbusBinding:408  ] - modbusSlave 'slave1' instanciated
10:50:11.169 [DEBUG] [.b.http.internal.HttpActivator:34   ] - HTTP binding has been started.
10:50:11.185 [INFO ] [.service.AbstractActiveService:169  ] - HTTP Refresh Service has been started
10:50:11.278 [DEBUG] [.o.b.snmp.internal.SnmpBinding:213  ] - Received PDU from '192.168.1.251/161' 'RESPONSE[requestID=1913325855, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.
1.2.1.2.2.1.8.41 = 1]]'
10:50:11.294 [INFO ] [runtime.busevents             :26   ] - Camera_11 state updated to ON
10:50:11.388 [DEBUG] [inding.ntp.internal.NtpBinding:83   ] - Got time from pool.ntp.org: Thursday, March 17, 2016 10:50:11 AM CDT
10:50:11.388 [INFO ] [runtime.busevents             :26   ] - Date state updated to 2016-03-17T10:50:11

ssalonen · March 17, 2016, 5:06pm

Thanks for the logs.

So just to double confirm I understand correctly:

you are using 1.8.1 with v6 version of the modbus binding
there is nothing regarding modbus after that?

Thanks! I need to test this myself as well again