[SNMP4SDN-14] ERROR message in distribution sanity check Created: 02/Feb/16  Updated: 19/Oct/17  Resolved: 15/Feb/16

Status: Resolved
Project: snmp4sdn
Component/s: General
Affects Version/s: unspecified
Fix Version/s: None

Type: Bug
Reporter: Luis Gomez Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: All
Platform: All


External issue ID: 5194

 Description   

Following ERROR is seeing when bringing snmp4sdn feature:

2016-02-02 04:21:52,476 | ERROR | Event Dispatcher | CmethUtil | 466 - org.opendaylight.snmp4sdn - 0.3.0.SNAPSHOT | CmethUtil.readDB() err: {}
java.io.FileNotFoundException: /etc/snmp4sdn_swdb.csv (No such file or directory)
at java.io.FileInputStream.open0(Native Method)[:1.8.0_65]
at java.io.FileInputStream.open(FileInputStream.java:195)[:1.8.0_65]
at java.io.FileInputStream.<init>(FileInputStream.java:138)[:1.8.0_65]
at java.io.FileInputStream.<init>(FileInputStream.java:93)[:1.8.0_65]
at java.io.FileReader.<init>(FileReader.java:58)[:1.8.0_65]
at org.opendaylight.snmp4sdn.internal.util.CmethUtil.readDB(CmethUtil.java:66)
at org.opendaylight.snmp4sdn.internal.util.CmethUtil.<init>(CmethUtil.java:43)
at org.opendaylight.snmp4sdn.core.internal.Controller.init(Controller.java:156)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_65]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_65]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_65]
at java.lang.reflect.Method.invoke(Method.java:497)[:1.8.0_65]
at org.apache.felix.dm.InvocationUtil.invokeMethod(InvocationUtil.java:111)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.InvocationUtil.invokeCallbackMethod(InvocationUtil.java:66)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.impl.ComponentImpl.invokeCallbackMethod(ComponentImpl.java:688)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.impl.ComponentImpl.invoke(ComponentImpl.java:679)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.impl.ComponentImpl.activateService(ComponentImpl.java:608)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.impl.ComponentImpl.access$000(ComponentImpl.java:52)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.impl.ComponentImpl$1.run(ComponentImpl.java:144)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.impl.SerialExecutor$1.run(SerialExecutor.java:47)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.impl.SerialExecutor.scheduleNext(SerialExecutor.java:84)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.impl.SerialExecutor.execute(SerialExecutor.java:68)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.impl.ComponentImpl.calculateStateChanges(ComponentImpl.java:231)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.impl.ComponentImpl.start(ComponentImpl.java:399)[220:org.apache.felix.dependencymanager:3.1.0]
at org.apache.felix.dm.DependencyManager.add(DependencyManager.java:169)
at org.opendaylight.controller.sal.core.ComponentActivatorAbstractBase.start(ComponentActivatorAbstractBase.java:346)
at org.opendaylight.snmp4sdn.internal.Activator.start(Activator.java:138)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(BundleContextImpl.java:711)
at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_65]
at org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(BundleContextImpl.java:702)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(BundleContextImpl.java:683)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:381)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(AbstractBundle.java:390)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Framework.java:1176)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:559)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:544)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(StartLevelManager.java:457)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:243)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:438)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:1)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]
at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)[org.eclipse.osgi-3.8.2.v20130124-134944.jar:]



 Comments   
Comment by Christine Hsieh [ 03/Feb/16 ]

This bug is fine. snmp4sdn plugin tries to read a file during start, for user's convenience. The read file failure won't harm snmp4sdn plugin nor whole system. Actually it is the switch list file, which is necessary for topology discovery for snmp4sdn plugin. snmp4sdn plugin provides command for user to manually assign the file path and trigger topology discovery.

Comment by Vratko Polak [ 03/Feb/16 ]

> The read file failure won't harm snmp4sdn plugin nor whole system.

Then it should not be logged as ERROR.
INFO about default config file not found (if it is really optional), or WARN if users should create such file.

Comment by Luis Gomez [ 03/Feb/16 ]

Right, I reopened this to see if snmp4sdn can change the log severity to WARN or INFO as future sanity checks will block everything in case of karaf ERROR.

Comment by A H [ 04/Feb/16 ]

Luis, do you think the bug should be marked as "major" since Yi-Ling Hsieh mentions this bug is fine.

Comment by Luis Gomez [ 04/Feb/16 ]

Sure, I just did.

Comment by Christine Hsieh [ 05/Feb/16 ]

Thanks Luis, I modified the error as INFO level, merged as https://git.opendaylight.org/gerrit/#/c/34052/

Comment by Jamo Luhrsen [ 10/Feb/16 ]

In my opinion, having full traces in the logs is very alarming and we should
avoid those if possible. I usually assume the software has encountered
something unexpected or is broken. In this case, we know that there are
times when the file might not be there. If that's reasonable, then can
we do something like this instead:

https://git.opendaylight.org/gerrit/#/c/34364

I'm not a java person, but it allows for the generic exception to still
be caught, but also the specific FileNotFound exception to be there in
a more tame fasion. Looks like this now:

016-02-09 21:56:06,489 | INFO | l for user karaf | CmethUtil | 242 - org.opendaylight.snmp4sdn - 0.3.0.SNAPSHOT | enter CmethUtil.readDB()
2016-02-09 21:56:06,489 | INFO | l for user karaf | CmethUtil | 242 - org.opendaylight.snmp4sdn - 0.3.0.SNAPSHOT | open file /etc/snmp4sdn_swdb.csv
2016-02-09 21:56:06,489 | INFO | l for user karaf | CmethUtil | 242 - org.opendaylight.snmp4sdn - 0.3.0.SNAPSHOT | CmethUtil.readDB() fail: /etc/snmp4
sdn_swdb.csv (No such file or directory)
2016-02-09 21:56:06,490 | INFO | l for user karaf | Controller | 242 - org.opendaylight.snmp4sdn - 0.3.0.SNAPSHOT | snmp4sdn's Controller: Starting!

Comment by Jamo Luhrsen [ 10/Feb/16 ]

I moved this back to an open state, just to continue the conversation, if
that's ok.

There is another exception coming from snmp4sdn:

2016-02-09 22:04:41,723 | WARN | l for user karaf | SNMPListener | 242 - org.opendaylight.snmp4sdn - 0.3.0.SNAPSHOT | Problem starting SNMP Trap Interfac
e: {}
java.net.BindException: Permission denied
at java.net.PlainDatagramSocketImpl.bind0(Native Method)[:1.7.0_95]
at java.net.AbstractPlainDatagramSocketImpl.bind(AbstractPlainDatagramSocketImpl.java:96)[:1.7.0_95]
at java.net.DatagramSocket.bind(DatagramSocket.java:397)[:1.7.0_95]
at java.net.DatagramSocket.<init>(DatagramSocket.java:251)[:1.7.0_95]
<snip>

this is also alarming, but I'm not sure the right thing to do. The reason for
the exception is that we are trying to bind on the well known SNMP trap port of
162. But, that's a privileged port ( < 1024) so only root user can do so.

our jenkins jobs are using a non-root user, I guess, so we see this is CSIT
every time. But, if we run karaf as root user (I tried) the port is successfully
bound to and no exceptions.

Not sure the right thing, or if anything, to do on this one.

Comment by Christine Hsieh [ 12/Feb/16 ]

For the warn alarm above, pointed by Jamo Luhrsen

2016-02-09 22:04:41,723 | WARN | l for user karaf | SNMPListener | 242 - org.opendaylight.snmp4sdn - 0.3.0.SNAPSHOT | Problem starting SNMP Trap Interfac
e: {}
java.net.BindException: Permission denied
...

It's due to snmp4sdn plugin needs to listen to the SNMP port for SNMP traps (in order to detect link-down/up events if receiving SNMP trap sent from an Ethernet switch).

So user needs to launch Karaf with sufficient OS privilege, such as an administrator.

Comment by Jamo Luhrsen [ 13/Feb/16 ]

So, I have two patches for you:

https://git.opendaylight.org/gerrit/#/c/34364/
https://git.opendaylight.org/gerrit/#/c/34588/

Since I think you would agree that these Exceptions are coming from
reasonable situations that we can know about, I think we should
not spit out the Entire trace. I do think those come across as
extra alarming and these are not cases for that. The above two
patches would instead give log messages like this:

2016-02-12 20:10:20,732 | INFO | l for user karaf | CmethUtil | 242 - org.opendaylight.snmp4sdn - 0.3.0.SNAPSHOT | CmethUtil.readDB() fail: /etc/snmp4sdn_swdb.csv (No such file or director
y)
2016-02-12 20:10:20,733 | INFO | l for user karaf | Controller | 242 - org.opendaylight.snmp4sdn - 0.3.0.SNAPSHOT | snmp4sdn's Controller: Starting!
2016-02-12 20:10:20,740 | WARN | l for user karaf | SNMPListener | 242 - org.opendaylight.snmp4sdn - 0.3.0.SNAPSHOT | Unable to Bind to SNMP Trap Port: Permission denied

I can modify the patches somehow if you feel neccessary.

Thanks.

Comment by Christine Hsieh [ 13/Feb/16 ]

Thanks for the patches, introduced into snmp4sdn repo.

Comment by Christine Hsieh [ 13/Feb/16 ]

Fixed, close this bug.

Comment by A H [ 15/Feb/16 ]

Severity: Not a blocker. We can release Beryllium without it.
Testing: Improved log messages instead of spitting out the entire trace. Extensive testing not necessary as the fix has very small footprint. This is not covered by any unit tests or system tests.
Impact: No impact to dependent projects.

Generated at Wed Feb 07 20:39:18 UTC 2024 using Jira 8.20.10#820010-sha1:ace47f9899e9ee25d7157d59aa17ab06aee30d3d.