search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.9k stars 3.59k forks source link

[snmp] trap receive port != 0 blocking entire binding #17550

Closed philipherbert closed 1 week ago

philipherbert commented 1 month ago

after switching version from 4.1.2 to 4.2.2 snmp binding would no longer start until the snmp trap receiving port is changed to 0 (trap receiver disabled)

issue is seen by other users https://community.openhab.org/t/snmp-seems-not-to-work-as-expected/157319/18

port 8162 that was previously used is not blocked by another application/container.

tried other ports also - no luck.

no change has been made to the docker host environment, the openhab/openhab container was simply replaced with the new version, preserving the configuration.

philipherbert commented 1 month ago

now tried a setup without without docker. As soon as I set the trap receiver port to something other than 0, the binding no longer communicates and polls. I have verified this with tcpdump sniffing for traffic on port 161.

so issue seems to be not only docker related. openhab 4.2.2 any ideas ?

lsiepel commented 2 weeks ago

Could you set the binding logging at Debug level and start the snmp thing. ?

Looked at the code and might have some clues, but need to verify this with your debug log.

philipherbert commented 2 weeks ago

changed port from 0 to 6163 and disabled and re-enabled one snmp thing that now fails to query:

2024-11-01 17:27:24.222 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.2.2 (284)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(357)] : ImmediateComponentHolder Finished configuring the dependency managers for component for pid binding.snmp 
2024-11-01 17:27:24.225 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.2.2 (284)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(357)] : ImmediateComponentHolder Will not enable component for pid binding.snmp: holder enabled state: true, metadata enabled: true 
2024-11-01 17:27:24.227 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.2.2 (284)[org.openhab.binding.snmp.internal.SnmpServiceImpl(358)] : ConfigurableComponentHolder configuration updated for pid binding.snmp with change count 12
2024-11-01 17:27:24.228 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.2.2 (284)[org.openhab.binding.snmp.internal.SnmpServiceImpl(358)] : Querying state active
2024-11-01 17:27:24.228 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.2.2 (284)[org.openhab.binding.snmp.internal.SnmpServiceImpl(358)] : Querying state active
2024-11-01 17:27:24.229 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.2.2 (284)[org.openhab.binding.snmp.internal.SnmpServiceImpl(358)] : getting modified: modified
2024-11-01 17:27:24.231 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.2.2 (284)[org.openhab.binding.snmp.internal.SnmpServiceImpl(358)] : Locating method modified in class org.openhab.binding.snmp.internal.SnmpServiceImpl
2024-11-01 17:27:24.232 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.2.2 (284)[org.openhab.binding.snmp.internal.SnmpServiceImpl(358)] : Declared Method org.openhab.binding.snmp.internal.SnmpServiceImpl.modified([interface org.osgi.service.component.ComponentContext]) not found
2024-11-01 17:27:24.233 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.2.2 (284)[org.openhab.binding.snmp.internal.SnmpServiceImpl(358)] : Found modified method: protected void org.openhab.binding.snmp.internal.SnmpServiceImpl.modified(java.util.Map)
2024-11-01 17:27:24.234 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.2.2 (284)[org.openhab.binding.snmp.internal.SnmpServiceImpl(358)] : invoking modified: modified: parameters [org.apache.felix.scr.impl.helper.ReadOnlyDictionary]
2024-11-01 17:27:24.301 [ERROR] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.2.2 (284)[org.openhab.binding.snmp.internal.SnmpServiceImpl(358)] : The modified method has thrown an exception
java.lang.RuntimeException: java.net.UnknownHostException: openhab-openhab4.2.2: openhab-openhab4.2.2: Name or service not known
    at org.snmp4j.smi.UdpAddress.<init>(UdpAddress.java:65) ~[?:?]
    at org.openhab.binding.snmp.internal.SnmpServiceImpl.modified(SnmpServiceImpl.java:95) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:569) ~[?:?]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:245) ~[bundleFile:?]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) ~[bundleFile:?]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:687) ~[bundleFile:?]
    at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:531) [bundleFile:?]
    at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:317) [bundleFile:?]
    at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:307) [bundleFile:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeModifiedMethod(SingleComponentManager.java:856) [bundleFile:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.modify(SingleComponentManager.java:810) [bundleFile:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.reconfigure(SingleComponentManager.java:725) [bundleFile:?]
    at org.apache.felix.scr.impl.manager.SingleComponentManager.reconfigure(SingleComponentManager.java:686) [bundleFile:?]
    at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.configurationUpdated(ConfigurableComponentHolder.java:440) [bundleFile:?]
    at org.apache.felix.scr.impl.manager.RegionConfigurationSupport.configurationEvent(RegionConfigurationSupport.java:347) [bundleFile:?]
    at org.apache.felix.scr.impl.manager.RegionConfigurationSupport$2.configurationEvent(RegionConfigurationSupport.java:115) [bundleFile:?]
    at org.apache.felix.cm.impl.ConfigurationManager$FireConfigurationEvent.sendEvent(ConfigurationManager.java:1723) [bundleFile:?]
    at org.apache.felix.cm.impl.ConfigurationManager$FireConfigurationEvent.run(ConfigurationManager.java:1664) [bundleFile:?]
    at org.apache.felix.cm.impl.UpdateThread.run0(UpdateThread.java:122) [bundleFile:?]
    at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:84) [bundleFile:?]
    at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.net.UnknownHostException: openhab-openhab4.2.2: openhab-openhab4.2.2: Name or service not known
    at java.net.InetAddress.getLocalHost(InetAddress.java:1671) ~[?:?]
    at org.snmp4j.smi.UdpAddress.<init>(UdpAddress.java:63) ~[?:?]
    ... 23 more
Caused by: java.net.UnknownHostException: openhab-openhab4.2.2: Name or service not known
    at java.net.Inet6AddressImpl.lookupAllHostAddr(Native Method) ~[?:?]
    at java.net.InetAddress$PlatformNameService.lookupAllHostAddr(InetAddress.java:934) ~[?:?]
    at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1543) ~[?:?]
    at java.net.InetAddress$NameServiceAddresses.get(InetAddress.java:852) ~[?:?]
    at java.net.InetAddress.getAllByName0(InetAddress.java:1533) ~[?:?]
    at java.net.InetAddress.getLocalHost(InetAddress.java:1666) ~[?:?]
    at org.snmp4j.smi.UdpAddress.<init>(UdpAddress.java:63) ~[?:?]
    ... 23 more
lsiepel commented 2 weeks ago

Yes, UnknownHostException as I expected.

I don't have docker, so need some details. Can you share to what interface / ip the openHAB itself is configured, could it be possible that IPv6 is configured? The binding tries to get the InetAddress.getLocalHost() and fails to do so. It might be docker configuration related.

philipherbert commented 2 weeks ago

I tried the snmp binding a few weeks ago on openhabian(rpi5). The same issue. So this can not only be docker related.

I changed the subject of this issue (remved docker) for this reason. The log was now created with openhab on docker, as the pi is not currently next to me.

Is it easier for you to proceed with the binding running on openhabian ? On the docker host, ipv6 is not activly configured.

lsiepel commented 2 weeks ago

It is somehow related to the network config. Not necessarily to docker, but yes docker might make it a little more complicated.

If you could run it on host, and share the network details. Both os and openHAB configs it would help I guess. Please also provide logs for that build just to make sure the issue is _exactly _the same.

philipherbert commented 2 weeks ago

the error message looks different, the result is the same. As soon as the binding starts with the port set, the bnding will fail. Once failed re-enabling an snmp thing does not help, the bundle needs to be restarted, when the port is set to 0.

eth0: flags=4163<UP,BROADCAST,RUNNING,MULTICAST>  mtu 1500
        inet 192.168.121.210  netmask 255.255.255.224  broadcast 192.168.121.223
        inet6 fe80::dd3f:305d:3667:7d55  prefixlen 64  scopeid 0x20<link>
        ether 2c:cf:67:6d:c3:23  txqueuelen 1000  (Ethernet)
        RX packets 7099  bytes 2541217 (2.4 MiB)
        RX errors 0  dropped 14  overruns 0  frame 0
        TX packets 1608  bytes 447821 (437.3 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
        device interrupt 111

lo: flags=73<UP,LOOPBACK,RUNNING>  mtu 65536
        inet 127.0.0.1  netmask 255.0.0.0
        inet6 ::1  prefixlen 128  scopeid 0x10<host>
        loop  txqueuelen 1000  (Local Loopback)
        RX packets 244  bytes 35689 (34.8 KiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 244  bytes 35689 (34.8 KiB)
        TX errors 0  dropped 0 overruns 0  carrier 0  collisions 0
2024-11-01 20:43:54.924 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.2.2 (272)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(374)] : Declared Method org.openhab.binding.snmp.internal.SnmpHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-11-01 20:43:54.924 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.2.2 (272)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(374)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2024-11-01 20:43:54.924 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.2.2 (272)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(374)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
2024-11-01 20:43:54.925 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.2.2 (272)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(374)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2024-11-01 20:43:54.925 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.2.2 (272)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(374)] : invoked activate: activate
2024-11-01 20:43:54.926 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.2.2 (272)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(374)] : Set implementation object for component
2024-11-01 20:43:54.926 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.2.2 (272)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(374)] : Changed state from satisfied to active
2024-11-01 20:43:54.928 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.2.2 (272)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(374)] : dm $000 tracking 2 SingleStatic added {org.openhab.binding.snmp.internal.SnmpService}={port=9163, service.id=565, service.bundleid=272, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), service.pid=binding.snmp, component.name=org.openhab.binding.snmp.internal.SnmpServiceImpl, component.id=375} (exit)
2024-11-01 20:43:55.389 [INFO ] [ding.snmp.internal.SnmpTargetHandler] - Could not send PDU
org.snmp4j.MessageException: Invalid argument
        at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:655) ~[?:?]
        at org.snmp4j.Snmp.sendMessage(Snmp.java:1074) ~[?:?]
        at org.snmp4j.Snmp.send(Snmp.java:1044) ~[?:?]
        at org.snmp4j.Snmp.send(Snmp.java:1031) ~[?:?]
        at org.openhab.binding.snmp.internal.SnmpServiceImpl.send(SnmpServiceImpl.java:179) ~[?:?]
        at org.openhab.binding.snmp.internal.SnmpTargetHandler.refresh(SnmpTargetHandler.java:598) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
        at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.net.SocketException: Invalid argument
        at sun.nio.ch.DatagramChannelImpl.send0(Native Method) ~[?:?]
        at sun.nio.ch.DatagramChannelImpl.sendFromNativeBuffer(DatagramChannelImpl.java:901) ~[?:?]
        at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:863) ~[?:?]
        at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:821) ~[?:?]
        at sun.nio.ch.DatagramChannelImpl.blockingSend(DatagramChannelImpl.java:853) ~[?:?]
        at sun.nio.ch.DatagramSocketAdaptor.send(DatagramSocketAdaptor.java:218) ~[?:?]
        at java.net.DatagramSocket.send(DatagramSocket.java:664) ~[?:?]
        at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:128) ~[?:?]
        at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:46) ~[?:?]
        at org.snmp4j.MessageDispatcherImpl.sendMessage(MessageDispatcherImpl.java:270) ~[?:?]
        at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:632) ~[?:?]
        ... 11 more
2024-11-01 20:43:56.890 [WARN ] [ding.snmp.internal.SnmpTargetHandler] - snmp:target:dc44a5057c requested GET[requestID=1181629191, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]] and got error: Invalid argument
^C
lsiepel commented 2 weeks ago

Atleast the UnknownHostException is gone, while it may still be network related. I created a new jar without functional changes just some additional logging.

https://1drv.ms/u/s!AnMcxmvEeupwj4tLGf_YXGbK25uGKg?e=OGgHLY

  1. Make sure you have openHAB 4.2.x or 4.3.0
  2. Uninstall the current binding (all things, channels and configuration remains available)
  3. Drop the jar into your addon folder.
  4. Set the binding log level at trace and post it here.

Hopefully this gives some more leads.

philipherbert commented 2 weeks ago

what is snmp at 127.0.1.1 ?

273 │ Active │ 80 │ 4.3.0.202411012128 │ openHAB Add-ons :: Bundles :: SNMP Binding

2024-11-01 21:43:49.016 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Querying state active
2024-11-01 21:43:49.017 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Deactivating component
2024-11-01 21:43:49.017 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : registration change queue [unregistered]
2024-11-01 21:43:49.024 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Querying state active
2024-11-01 21:43:49.025 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : getting deactivate: deactivate
2024-11-01 21:43:49.025 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Locating method deactivate in class org.openhab.binding.snmp.internal.SnmpHandlerFactory
2024-11-01 21:43:49.025 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Declared Method org.openhab.binding.snmp.internal.SnmpHandlerFactory.deactivate([interface org.osgi.service.component.ComponentContext]) not found
2024-11-01 21:43:49.026 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Locating method deactivate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2024-11-01 21:43:49.026 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Found deactivate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.deactivate(org.osgi.service.component.ComponentContext)
2024-11-01 21:43:49.026 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : invoking deactivate: deactivate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2024-11-01 21:43:49.027 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : invoked deactivate: deactivate
2024-11-01 21:43:49.027 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : DependencyManager: osgi.ds.satisfying.condition close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@3302fb6 at tracking count 1 refpairs: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-11-01 21:43:49.028 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : DependencyManager: $000 close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@3302fb6 at tracking count 2 refpairs: [[RefPair: ref: [{org.openhab.binding.snmp.internal.SnmpService}={port=9163, service.id=579, service.bundleid=273, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), service.pid=binding.snmp, component.name=org.openhab.binding.snmp.internal.SnmpServiceImpl, component.id=384}] service: [org.openhab.binding.snmp.internal.SnmpServiceImpl@3c09121f]]]
2024-11-01 21:43:49.028 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Unset and deconfigured implementation object for component in deleteComponent for reason Unspecified
2024-11-01 21:43:49.028 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Changed state from active to satisfied
2024-11-01 21:43:49.029 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Deactivating dependency managers
2024-11-01 21:43:49.029 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Querying state active
2024-11-01 21:43:49.029 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : getting deactivate: deactivate
2024-11-01 21:43:49.030 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Locating method deactivate in class org.openhab.binding.snmp.internal.SnmpServiceImpl
2024-11-01 21:43:49.030 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Declared Method org.openhab.binding.snmp.internal.SnmpServiceImpl.deactivate([interface org.osgi.service.component.ComponentContext]) not found
2024-11-01 21:43:49.030 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Found deactivate method: public void org.openhab.binding.snmp.internal.SnmpServiceImpl.deactivate()
2024-11-01 21:43:49.030 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : invoking deactivate: deactivate: parameters []
2024-11-01 21:43:49.031 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : invoked deactivate: deactivate
2024-11-01 21:43:49.032 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : DependencyManager: osgi.ds.satisfying.condition close component unbinding from org.apache.felix.scr.impl.manager.ComponentContextImpl@5ee4a9c2 at tracking count 1 refpairs: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-11-01 21:43:49.032 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Unset and deconfigured implementation object for component in deleteComponent for reason Unspecified
2024-11-01 21:43:49.032 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Changed state from active to satisfied
2024-11-01 21:43:49.032 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Disabling dependency managers
2024-11-01 21:43:49.033 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : unregistering service listener for dependency $000
2024-11-01 21:43:49.033 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : unregistering service listener for dependency osgi.ds.satisfying.condition
2024-11-01 21:43:49.033 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Querying state satisfied
2024-11-01 21:43:49.034 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Changed state from satisfied to disposed
2024-11-01 21:43:49.034 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(383)] : Disposing component (reason: 6)
2024-11-01 21:43:49.034 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Querying state satisfied
2024-11-01 21:43:49.034 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Deactivating component
2024-11-01 21:43:49.035 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : registration change queue [unregistered]
2024-11-01 21:43:49.036 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Deactivating dependency managers
2024-11-01 21:43:49.036 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Disabling dependency managers
2024-11-01 21:43:49.036 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : unregistering service listener for dependency osgi.ds.satisfying.condition
2024-11-01 21:43:49.037 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Querying state satisfied
2024-11-01 21:43:49.037 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Changed state from satisfied to disposed
2024-11-01 21:43:49.037 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(384)] : Disposing component (reason: 6)
2024-11-01 21:43:49.042 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory] : BundleComponentActivator : ComponentHolder created.
2024-11-01 21:43:49.042 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl] : BundleComponentActivator : ComponentHolder created.
2024-11-01 21:43:49.044 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory] : ConfigurableComponentHolder configuration updated for pid binding.snmp with change count 14
2024-11-01 21:43:49.045 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl] : ConfigurableComponentHolder configuration updated for pid binding.snmp with change count 14
2024-11-01 21:43:49.046 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory] : Dependency Manager created $000interface=org.openhab.binding.snmp.internal.SnmpService, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=service, parameter=0
2024-11-01 21:43:49.046 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory] : Dependency Manager created osgi.ds.satisfying.conditioninterface=org.osgi.service.condition.Condition, filter=(osgi.condition.id=true), policy=dynamic, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2024-11-01 21:43:49.047 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory] : Component created: DS=DS14, implementation=org.openhab.binding.snmp.internal.SnmpHandlerFactory, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[binding.snmp]
2024-11-01 21:43:49.047 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory]
2024-11-01 21:43:49.047 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2024-11-01 21:43:49.048 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory] : Querying state disabled
2024-11-01 21:43:49.048 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory] : Querying state disabled
2024-11-01 21:43:49.048 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory] : Component can not be activated since it is in state disabled
2024-11-01 21:43:49.048 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory] : Querying state disabled
2024-11-01 21:43:49.049 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Updating target filters
2024-11-01 21:43:49.049 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : No change in target property for dependency $000: currently registered: false
2024-11-01 21:43:49.049 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] :  No existing service listener to unregister for dependency $000
2024-11-01 21:43:49.049 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Setting target property for dependency $000 to null
2024-11-01 21:43:49.050 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : New service tracker for $000, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.binding.snmp.internal.SnmpService), initialReferenceFilter (objectClass=org.openhab.binding.snmp.internal.SnmpService)
2024-11-01 21:43:49.050 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : dm $000 tracker reset (closed)
2024-11-01 21:43:49.050 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : dm $000 tracker opened
2024-11-01 21:43:49.051 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : registering service listener for dependency $000
2024-11-01 21:43:49.051 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2024-11-01 21:43:49.051 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2024-11-01 21:43:49.051 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2024-11-01 21:43:49.052 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2024-11-01 21:43:49.052 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : dm osgi.ds.satisfying.condition tracking 1 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2024-11-01 21:43:49.053 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : dm osgi.ds.satisfying.condition tracking 1 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2024-11-01 21:43:49.053 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : dm osgi.ds.satisfying.condition tracker opened
2024-11-01 21:43:49.053 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : registering service listener for dependency osgi.ds.satisfying.condition
2024-11-01 21:43:49.053 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Changed state from disabled to unsatisfiedReference
2024-11-01 21:43:49.054 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Component enabled
2024-11-01 21:43:49.054 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : ActivateInternal
2024-11-01 21:43:49.054 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.054 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.055 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Activating component from state unsatisfiedReference
2024-11-01 21:43:49.055 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.055 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.055 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Dependency not satisfied: $000
2024-11-01 21:43:49.056 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Not all dependencies satisfied, cannot activate
2024-11-01 21:43:49.056 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl] : Dependency Manager created osgi.ds.satisfying.conditioninterface=org.osgi.service.condition.Condition, filter=(osgi.condition.id=true), policy=dynamic, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2024-11-01 21:43:49.056 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl] : Component created: DS=DS14, implementation=org.openhab.binding.snmp.internal.SnmpServiceImpl, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=modified configuration-pid=[binding.snmp]
2024-11-01 21:43:49.056 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl] : Component Services: scope=singleton, services=[org.openhab.binding.snmp.internal.SnmpService]
2024-11-01 21:43:49.057 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl] : Component Properties: {osgi.ds.satisfying.condition.target=(osgi.condition.id=true)}
2024-11-01 21:43:49.057 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl] : Querying state disabled
2024-11-01 21:43:49.057 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl] : Querying state disabled
2024-11-01 21:43:49.058 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl] : Component can not be activated since it is in state disabled
2024-11-01 21:43:49.058 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl] : Querying state disabled
2024-11-01 21:43:49.058 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Updating target filters
2024-11-01 21:43:49.058 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] :  No existing service listener to unregister for dependency osgi.ds.satisfying.condition
2024-11-01 21:43:49.059 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Setting target property for dependency osgi.ds.satisfying.condition to (osgi.condition.id=true)
2024-11-01 21:43:49.059 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : New service tracker for osgi.ds.satisfying.condition, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.condition.Condition), initialReferenceFilter (&(objectClass=org.osgi.service.condition.Condition)(osgi.condition.id=true))
2024-11-01 21:43:49.059 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : dm osgi.ds.satisfying.condition tracker reset (closed)
2024-11-01 21:43:49.060 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : dm osgi.ds.satisfying.condition tracking 1 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (enter)
2024-11-01 21:43:49.060 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : dm osgi.ds.satisfying.condition tracking 1 SingleDynamic added {org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true} (exit)
2024-11-01 21:43:49.060 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : dm osgi.ds.satisfying.condition tracker opened
2024-11-01 21:43:49.060 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : registering service listener for dependency osgi.ds.satisfying.condition
2024-11-01 21:43:49.061 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Changed state from disabled to unsatisfiedReference
2024-11-01 21:43:49.061 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Component enabled
2024-11-01 21:43:49.061 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : ActivateInternal
2024-11-01 21:43:49.061 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.062 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.062 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Activating component from state unsatisfiedReference
2024-11-01 21:43:49.062 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.062 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.063 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Changed state from unsatisfiedReference to satisfied
2024-11-01 21:43:49.063 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : registration change queue [registered]
2024-11-01 21:43:49.064 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : dm $000 tracking 2 SingleStatic added {org.openhab.binding.snmp.internal.SnmpService}={port=9163, service.id=582, service.bundleid=273, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), service.pid=binding.snmp, component.name=org.openhab.binding.snmp.internal.SnmpServiceImpl, component.id=386} (enter)
2024-11-01 21:43:49.064 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : ActivateInternal
2024-11-01 21:43:49.065 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.065 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.065 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Activating component from state unsatisfiedReference
2024-11-01 21:43:49.065 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.066 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Querying state unsatisfiedReference
2024-11-01 21:43:49.066 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Changed state from unsatisfiedReference to satisfied
2024-11-01 21:43:49.066 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : registration change queue [registered]
2024-11-01 21:43:49.067 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Checking constructor public org.openhab.binding.snmp.internal.SnmpHandlerFactory(org.openhab.binding.snmp.internal.SnmpService)
2024-11-01 21:43:49.067 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : getClassFromComponentClassLoader: Looking for interface class org.openhab.binding.snmp.internal.SnmpService through loader of org.openhab.binding.snmp.internal.SnmpHandlerFactory
2024-11-01 21:43:49.068 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : getClassFromComponentClassLoader: Found class org.openhab.binding.snmp.internal.SnmpService
2024-11-01 21:43:49.068 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Found constructor with 1 arguments : public org.openhab.binding.snmp.internal.SnmpHandlerFactory(org.openhab.binding.snmp.internal.SnmpService)
2024-11-01 21:43:49.068 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : This thread collected dependencies
2024-11-01 21:43:49.069 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : getService (single component manager) dependencies collected.
2024-11-01 21:43:49.069 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Querying state satisfied
2024-11-01 21:43:49.069 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Querying state satisfied
2024-11-01 21:43:49.069 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.binding.snmp.internal.SnmpService}={port=9163, service.id=582, service.bundleid=273, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), service.pid=binding.snmp, component.name=org.openhab.binding.snmp.internal.SnmpServiceImpl, component.id=386}] service: [null]]]
2024-11-01 21:43:49.070 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-11-01 21:43:49.070 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Checking constructor public org.openhab.binding.snmp.internal.SnmpServiceImpl(java.util.Map)
2024-11-01 21:43:49.071 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Found constructor with 1 arguments : public org.openhab.binding.snmp.internal.SnmpServiceImpl(java.util.Map)
2024-11-01 21:43:49.071 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : This thread collected dependencies
2024-11-01 21:43:49.071 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : getService (single component manager) dependencies collected.
2024-11-01 21:43:49.071 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Querying state satisfied
2024-11-01 21:43:49.072 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Querying state satisfied
2024-11-01 21:43:49.072 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : For dependency osgi.ds.satisfying.condition, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.condition.Condition}={service.id=6, service.bundleid=0, service.scope=singleton, service.pid=0.org.osgi.service.condition.ConditionImpl, osgi.condition.id=true}] service: [null]]]
2024-11-01 21:43:49.073 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - initialized SNMP at 127.0.1.1/9163
2024-11-01 21:43:49.074 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : getting activate: activate
2024-11-01 21:43:49.074 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Locating method activate in class org.openhab.binding.snmp.internal.SnmpServiceImpl
2024-11-01 21:43:49.075 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Declared Method org.openhab.binding.snmp.internal.SnmpServiceImpl.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-11-01 21:43:49.075 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Locating method activate in class java.lang.Object
2024-11-01 21:43:49.075 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-11-01 21:43:49.076 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : activate method [activate] not found, ignoring
2024-11-01 21:43:49.076 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Set implementation object for component
2024-11-01 21:43:49.076 [DEBUG] [inding.snmp.internal.SnmpServiceImpl] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpServiceImpl(386)] : Changed state from satisfied to active
2024-11-01 21:43:49.076 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : getting activate: activate
2024-11-01 21:43:49.077 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Locating method activate in class org.openhab.binding.snmp.internal.SnmpHandlerFactory
2024-11-01 21:43:49.077 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Declared Method org.openhab.binding.snmp.internal.SnmpHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found
2024-11-01 21:43:49.077 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory
2024-11-01 21:43:49.078 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext)
2024-11-01 21:43:49.078 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl]
2024-11-01 21:43:49.078 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : invoked activate: activate
2024-11-01 21:43:49.079 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Set implementation object for component
2024-11-01 21:43:49.079 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : Changed state from satisfied to active
2024-11-01 21:43:49.081 [DEBUG] [ing.snmp.internal.SnmpHandlerFactory] - bundle org.openhab.binding.snmp:4.3.0.202411012128 (273)[org.openhab.binding.snmp.internal.SnmpHandlerFactory(385)] : dm $000 tracking 2 SingleStatic added {org.openhab.binding.snmp.internal.SnmpService}={port=9163, service.id=582, service.bundleid=273, service.scope=bundle, osgi.ds.satisfying.condition.target=(osgi.condition.id=true), service.pid=binding.snmp, component.name=org.openhab.binding.snmp.internal.SnmpServiceImpl, component.id=386} (exit)
2024-11-01 21:43:49.289 [DEBUG] [ding.snmp.internal.SnmpTargetHandler] - init with version SNMPv1 or SNMPv2
2024-11-01 21:43:49.290 [TRACE] [ding.snmp.internal.SnmpTargetHandler] - Determined 192.168.121.194/161 as address for 192.168.121.194 (thing snmp:target:dc44a5057c)
2024-11-01 21:43:49.291 [TRACE] [inding.snmp.internal.SnmpServiceImpl] - Trying to send: 'GET[requestID=0, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]]'' to: 'CommunityTarget[address=192.168.121.194/161,version=1,timeout=1500,retries=2,securityLevel=1,securityModel=1,securityName=public,preferredTransports=null]'
2024-11-01 21:43:49.292 [INFO ] [ding.snmp.internal.SnmpTargetHandler] - Could not send PDU
org.snmp4j.MessageException: Invalid argument
    at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:655) ~[?:?]
    at org.snmp4j.Snmp.sendMessage(Snmp.java:1074) ~[?:?]
    at org.snmp4j.Snmp.send(Snmp.java:1044) ~[?:?]
    at org.snmp4j.Snmp.send(Snmp.java:1031) ~[?:?]
    at org.openhab.binding.snmp.internal.SnmpServiceImpl.send(SnmpServiceImpl.java:180) ~[?:?]
    at org.openhab.binding.snmp.internal.SnmpTargetHandler.refresh(SnmpTargetHandler.java:600) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
    at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.net.SocketException: Invalid argument
    at sun.nio.ch.DatagramChannelImpl.send0(Native Method) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.sendFromNativeBuffer(DatagramChannelImpl.java:901) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:863) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:821) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.blockingSend(DatagramChannelImpl.java:853) ~[?:?]
    at sun.nio.ch.DatagramSocketAdaptor.send(DatagramSocketAdaptor.java:218) ~[?:?]
    at java.net.DatagramSocket.send(DatagramSocket.java:664) ~[?:?]
    at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:128) ~[?:?]
    at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:46) ~[?:?]
    at org.snmp4j.MessageDispatcherImpl.sendMessage(MessageDispatcherImpl.java:270) ~[?:?]
    at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:632) ~[?:?]
    ... 11 more
2024-11-01 21:43:50.792 [WARN ] [ding.snmp.internal.SnmpTargetHandler] - snmp:target:dc44a5057c requested GET[requestID=1081863316, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]] and got error: Invalid argument
2024-11-01 21:44:49.294 [TRACE] [inding.snmp.internal.SnmpServiceImpl] - Trying to send: 'GET[requestID=0, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]]'' to: 'CommunityTarget[address=192.168.121.194/161,version=1,timeout=1500,retries=2,securityLevel=1,securityModel=1,securityName=public,preferredTransports=null]'
2024-11-01 21:44:49.295 [INFO ] [ding.snmp.internal.SnmpTargetHandler] - Could not send PDU
org.snmp4j.MessageException: Invalid argument
    at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:655) ~[?:?]
    at org.snmp4j.Snmp.sendMessage(Snmp.java:1074) ~[?:?]
    at org.snmp4j.Snmp.send(Snmp.java:1044) ~[?:?]
    at org.snmp4j.Snmp.send(Snmp.java:1031) ~[?:?]
    at org.openhab.binding.snmp.internal.SnmpServiceImpl.send(SnmpServiceImpl.java:180) ~[?:?]
    at org.openhab.binding.snmp.internal.SnmpTargetHandler.refresh(SnmpTargetHandler.java:600) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
    at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.net.SocketException: Invalid argument
    at sun.nio.ch.DatagramChannelImpl.send0(Native Method) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.sendFromNativeBuffer(DatagramChannelImpl.java:901) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:863) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:821) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.blockingSend(DatagramChannelImpl.java:853) ~[?:?]
    at sun.nio.ch.DatagramSocketAdaptor.send(DatagramSocketAdaptor.java:218) ~[?:?]
    at java.net.DatagramSocket.send(DatagramSocket.java:664) ~[?:?]
    at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:128) ~[?:?]
    at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:46) ~[?:?]
    at org.snmp4j.MessageDispatcherImpl.sendMessage(MessageDispatcherImpl.java:270) ~[?:?]
    at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:632) ~[?:?]
    ... 11 more
2024-11-01 21:44:50.796 [WARN ] [ding.snmp.internal.SnmpTargetHandler] - snmp:target:dc44a5057c requested GET[requestID=1081863317, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]] and got error: Invalid argument
2024-11-01 21:45:49.297 [TRACE] [inding.snmp.internal.SnmpServiceImpl] - Trying to send: 'GET[requestID=0, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]]'' to: 'CommunityTarget[address=192.168.121.194/161,version=1,timeout=1500,retries=2,securityLevel=1,securityModel=1,securityName=public,preferredTransports=null]'
2024-11-01 21:45:49.298 [INFO ] [ding.snmp.internal.SnmpTargetHandler] - Could not send PDU
org.snmp4j.MessageException: Invalid argument
    at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:655) ~[?:?]
    at org.snmp4j.Snmp.sendMessage(Snmp.java:1074) ~[?:?]
    at org.snmp4j.Snmp.send(Snmp.java:1044) ~[?:?]
    at org.snmp4j.Snmp.send(Snmp.java:1031) ~[?:?]
    at org.openhab.binding.snmp.internal.SnmpServiceImpl.send(SnmpServiceImpl.java:180) ~[?:?]
    at org.openhab.binding.snmp.internal.SnmpTargetHandler.refresh(SnmpTargetHandler.java:600) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
    at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.net.SocketException: Invalid argument
    at sun.nio.ch.DatagramChannelImpl.send0(Native Method) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.sendFromNativeBuffer(DatagramChannelImpl.java:901) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:863) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:821) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.blockingSend(DatagramChannelImpl.java:853) ~[?:?]
    at sun.nio.ch.DatagramSocketAdaptor.send(DatagramSocketAdaptor.java:218) ~[?:?]
    at java.net.DatagramSocket.send(DatagramSocket.java:664) ~[?:?]
    at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:128) ~[?:?]
    at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:46) ~[?:?]
    at org.snmp4j.MessageDispatcherImpl.sendMessage(MessageDispatcherImpl.java:270) ~[?:?]
    at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:632) ~[?:?]
    ... 11 more
2024-11-01 21:45:50.799 [WARN ] [ding.snmp.internal.SnmpTargetHandler] - snmp:target:dc44a5057c requested GET[requestID=1081863318, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]] and got error: Invalid argument
2024-11-01 21:46:49.301 [TRACE] [inding.snmp.internal.SnmpServiceImpl] - Trying to send: 'GET[requestID=0, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]]'' to: 'CommunityTarget[address=192.168.121.194/161,version=1,timeout=1500,retries=2,securityLevel=1,securityModel=1,securityName=public,preferredTransports=null]'
2024-11-01 21:46:49.302 [INFO ] [ding.snmp.internal.SnmpTargetHandler] - Could not send PDU
org.snmp4j.MessageException: Invalid argument
    at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:655) ~[?:?]
    at org.snmp4j.Snmp.sendMessage(Snmp.java:1074) ~[?:?]
    at org.snmp4j.Snmp.send(Snmp.java:1044) ~[?:?]
    at org.snmp4j.Snmp.send(Snmp.java:1031) ~[?:?]
    at org.openhab.binding.snmp.internal.SnmpServiceImpl.send(SnmpServiceImpl.java:180) ~[?:?]
    at org.openhab.binding.snmp.internal.SnmpTargetHandler.refresh(SnmpTargetHandler.java:600) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
    at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.net.SocketException: Invalid argument
    at sun.nio.ch.DatagramChannelImpl.send0(Native Method) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.sendFromNativeBuffer(DatagramChannelImpl.java:901) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:863) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:821) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.blockingSend(DatagramChannelImpl.java:853) ~[?:?]
    at sun.nio.ch.DatagramSocketAdaptor.send(DatagramSocketAdaptor.java:218) ~[?:?]
    at java.net.DatagramSocket.send(DatagramSocket.java:664) ~[?:?]
    at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:128) ~[?:?]
    at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:46) ~[?:?]
    at org.snmp4j.MessageDispatcherImpl.sendMessage(MessageDispatcherImpl.java:270) ~[?:?]
    at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:632) ~[?:?]
    ... 11 more
2024-11-01 21:46:50.802 [WARN ] [ding.snmp.internal.SnmpTargetHandler] - snmp:target:dc44a5057c requested GET[requestID=1081863319, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]] and got error: Invalid argument
2024-11-01 21:47:49.304 [TRACE] [inding.snmp.internal.SnmpServiceImpl] - Trying to send: 'GET[requestID=0, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]]'' to: 'CommunityTarget[address=192.168.121.194/161,version=1,timeout=1500,retries=2,securityLevel=1,securityModel=1,securityName=public,preferredTransports=null]'
2024-11-01 21:47:49.305 [INFO ] [ding.snmp.internal.SnmpTargetHandler] - Could not send PDU
org.snmp4j.MessageException: Invalid argument
    at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:655) ~[?:?]
    at org.snmp4j.Snmp.sendMessage(Snmp.java:1074) ~[?:?]
    at org.snmp4j.Snmp.send(Snmp.java:1044) ~[?:?]
    at org.snmp4j.Snmp.send(Snmp.java:1031) ~[?:?]
    at org.openhab.binding.snmp.internal.SnmpServiceImpl.send(SnmpServiceImpl.java:180) ~[?:?]
    at org.openhab.binding.snmp.internal.SnmpTargetHandler.refresh(SnmpTargetHandler.java:600) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
    at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: java.net.SocketException: Invalid argument
    at sun.nio.ch.DatagramChannelImpl.send0(Native Method) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.sendFromNativeBuffer(DatagramChannelImpl.java:901) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:863) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.send(DatagramChannelImpl.java:821) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.blockingSend(DatagramChannelImpl.java:853) ~[?:?]
    at sun.nio.ch.DatagramSocketAdaptor.send(DatagramSocketAdaptor.java:218) ~[?:?]
    at java.net.DatagramSocket.send(DatagramSocket.java:664) ~[?:?]
    at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:128) ~[?:?]
    at org.snmp4j.transport.DefaultUdpTransportMapping.sendMessage(DefaultUdpTransportMapping.java:46) ~[?:?]
    at org.snmp4j.MessageDispatcherImpl.sendMessage(MessageDispatcherImpl.java:270) ~[?:?]
    at org.snmp4j.MessageDispatcherImpl.sendPdu(MessageDispatcherImpl.java:632) ~[?:?]
    ... 11 more
2024-11-01 21:47:50.805 [WARN ] [ding.snmp.internal.SnmpTargetHandler] - snmp:target:dc44a5057c requested GET[requestID=1081863320, errorStatus=Success(0), errorIndex=0, VBS[1.3.6.1.2.1.1.3.0 = Null]] and got error: Invalid argument
philipherbert commented 2 weeks ago

i have found something interesting here: on openhabian there was an entry in /etc/hosts file for the hostname 'openhabian' to 127.0.1.1 On this openhabian the default ip is optained via dhcp. (default after install, never changed)

It seems as if the snmp binding tries to use this address to bind the trap receiver.

I have for testing purposes, changed this entry to the dynamic assigned ipv4 of the openhabian. After bundle restart, the issue seems solved.

Should the binding not register to

ifconfig shows 127.0.01 for the localhost, i can ping 127.0.1.1 .. no Idee if this is a bindable address

I have checked the docker container, there is also no 'real' hostname in the /etc/hosts file, but at least no entry for 127.0.1.1 But regadring docker: although i run openhab and several other containers, my knowledge is limited ...

something must have happened between docker container 4.1 and 4.1 for openhab (alpine ?) . Running 4.1 on docker the snmp binding worked.

docker exec -t hostname prints: openhab-openhab4.2.2 (the name of the docker container)

cat /etc/hosts 127.0.0.1 localhost ::1 localhost 127.0.0.1 rackstation ::1 rackstation

ipv6 is disabled in openhab config

lsiepel commented 2 weeks ago

Docker seemed to have an UnknownHostException and the stacktrace showed something regarding IPv6, but not 100% as we did not analyse that any further. But for sure it could not fullfill the InetAddress.getLocalHost() call. Edit: The ipv6 might be disabled in openHAB, it might still be enabled on OS level. This binding does not look at the openHAB config. One could argue this is good or bad, but for now this is what it is.

On the host, that exception was gone, but it's hostname lead to 127.0.1.1 instead of 127.0.0.1. I have no clue, how that got there and if it is set by you, some script or by openhabian's default image. If you want to, you could raise an issue at the openhabian repo.

Atleast the issue has been found and we do not need create a bug fix for the binding ;-)

philipherbert commented 2 weeks ago

well, it worked before updating docker image to 4.2.(on the same docker host, with the same ipv4 (configured), ipv6 (auto setting)

on docker it seems to be quite complicated to customize the host file.

how does the snmp binding know, which interface to bind to, when not reading the openhab config. (the ipv4 ist listed here, even when dynamic ip of the os is in use)

I see this is well documented here now, and might help others, but this blocking without any visible hint/message from the binding in UI does not seem ideal to me.

lsiepel commented 2 weeks ago

does the snmp binding know, which interface to bind to, when not reading the openhab config. (the ipv4 ist listed here, even when dynamic ip of the os is in use)

Actually this is not done by the binding but it is handled by the snmp4j lib (a dependency that this binding uses). While that lib also has an option to set the address manually it is currently set to 'determine it by itself'. For that lib uses the InetAddress.getLocalHost() that is a function that is available in java by default Docs here: https://docs.oracle.com/javase/6/docs/api/java/net/InetAddress.html#getLocalHost()

Returns the address of the local host. This is achieved by retrieving the name of the host from the system, then resolving that name into an InetAddress.

Referring to this code, the UdpAddress also provide a constructor with InetAddress and port. https://github.com/openhab/openhab-addons/blob/2080c85524d6798c01cddabd08644ab2fb33df24/bundles/org.openhab.binding.snmp/src/main/java/org/openhab/binding/snmp/internal/SnmpServiceImpl.java#L94-L98

philipherbert commented 2 weeks ago

I have now double checked old (running) and new configurations with this issue.

There where no changes regadring the hosts file / host names etc.

If i understand the changes to Openhab from Jun5 #16803, before (< 4.2) an older version of snmp4j was in use, so changes to smp4j must cause the issue with this type of configuration.

see also: https://community.openhab.org/t/snmp-seems-not-to-work-as-expected/157319/22

lsiepel commented 2 weeks ago

About the hosts file; changed or not, it pointed to the wrong address. That was the real issue. It may have been hidden (or not present) and with the updated snmp4j lib this configuration issue came to light.

only thing I can do is to change the log level to info for the log line that states the ip it is listening on. That way it will always be listed and easier to discover.

philipherbert commented 2 weeks ago

I fully agree the host address is the root cause. This seems to be default on several distribiutions when using dhcp.

However openhabian, when run as documented (dhcp server should always supply the same address) will run into this issue.

The same seems to apply to a default setup with docker. The Hostname ist set to the name of the assigned name of the docker container, the host file is not modified or set to the IP assigned via dhcp.

Perhaps this should be forwared to the maintainers of the documentation or the maintainers of openhabian / docker, as this binding will fail, when everything is setup as descibed on openhab.org/docs

Thanks for your help, the binding is up an running here again now.