[OPNFLWJAVA-71] Karaf log many WARNs when OVS 2.4 connects to controller Created: 01/Feb/16  Updated: 03/May/18  Resolved: 03/May/18

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

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

Operating System: All
Platform: All

Issue Links:
Duplicate
is duplicated by OPNFLWPLUG-564 Support table features in OVS 2.4 Resolved
External issue ID: 5173

 Description   

When I connect OVS 2.4 to controller, I see too many exceptions filling up several karaf log files. I understand some WARN or ERROR is needed but is it possible to reduce the number? If we cannot easily fix this, we can always release note this issue so users are not alarmed.

2016-01-29 18:36:05,600 | WARN | entLoopGroup-5-2 | ListDeserializer | 172 - org.opendaylight.openflowjava.openflow-protocol-impl - 0.7.0.SNAPSHOT | Problem during reading table feature property. Skipping unknown feature property: msgVersion: 4 objectClass: org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.oxm.rev150225.match.entries.grouping.MatchEntry msgType: 1 oxm_field: 31 experimenterID: null
java.lang.IllegalStateException: Deserializer for key: msgVersion: 4 objectClass: org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.oxm.rev150225.match.entries.grouping.MatchEntry msgType: 1 oxm_field: 31 experimenterID: null was not found - please verify that all needed deserializers ale loaded correctly
at org.opendaylight.openflowjava.protocol.impl.deserialization.DeserializerRegistryImpl.getDeserializer(DeserializerRegistryImpl.java:69)[172:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.util.ListDeserializer.deserializeHeaders(ListDeserializer.java:80)[172:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.deserialization.factories.MultipartReplyMessageFactory.createTableFeaturesProperties(MultipartReplyMessageFactory.java:444)[172:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.deserialization.factories.MultipartReplyMessageFactory.setTableFeatures(MultipartReplyMessageFactory.java:379)[172:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.deserialization.factories.MultipartReplyMessageFactory.deserialize(MultipartReplyMessageFactory.java:232)[172:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.deserialization.factories.MultipartReplyMessageFactory.deserialize(MultipartReplyMessageFactory.java:149)[172:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.deserialization.DeserializationFactory.deserialize(DeserializationFactory.java:59)[172:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.OFDecoder.decode(OFDecoder.java:55)[172:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at org.opendaylight.openflowjava.protocol.impl.core.OFDecoder.decode(OFDecoder.java:28)[172:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89)[125:io.netty.codec:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:318)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:304)[124:io.netty.transport:4.0.33.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:276)[125:io.netty.codec:4.0.33.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:263)[125:io.netty.codec:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:318)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:304)[124:io.netty.transport:4.0.33.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:276)[125:io.netty.codec:4.0.33.Final]
at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:354)[125:io.netty.codec:4.0.33.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:244)[125:io.netty.codec:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:318)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:304)[124:io.netty.transport:4.0.33.Final]
at io.netty.handler.timeout.ReadTimeoutHandler.channelRead(ReadTimeoutHandler.java:152)[127:io.netty.handler:4.0.33.Final]
at org.opendaylight.openflowjava.protocol.impl.core.IdleHandler.channelRead(IdleHandler.java:39)[172:org.opendaylight.openflowjava.openflow-protocol-impl:0.7.0.SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:318)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:304)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:318)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:304)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:846)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)[124:io.netty.transport:4.0.33.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:349)[124:io.netty.transport:4.0.33.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[123:io.netty.common:4.0.33.Final]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[123:io.netty.common:4.0.33.Final]
at java.lang.Thread.run(Thread.java:745)[:1.7.0_79]

 Comments   
Comment by Jose M. Alcaraz Calero [ 02/Feb/16 ]

This bug is directly related to the one I have reported: Bug ID: 5181. In fact, if the library "Nicira Extension" is installated, then the bug is the one I have reported. However, if you decide to remote such library to fix the "ClassCastExpection then the problem is exactly the one reported herein.

Comment by Michal Polkorab [ 02/Feb/16 ]

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

Comment by Michal Polkorab [ 03/Feb/16 ]

The change was merged - WARN message will be logged for EACH multipart reply (table features) - This should only provide hint with exception message. If details are desired, one has to set openflowjava logging to DEBUG and he will see complete exception.

Log frequency can't be adjusted beyond this point.

Comment by Luis Gomez [ 04/Feb/16 ]

Now I "only" get 1524 log entries like this:

2016-02-03 18:34:29,604 | WARN | entLoopGroup-5-2 | ListDeserializer | 172 - org.opendaylight.openflowjava.openflow-protocol-impl - 0.7.0.SNAPSHOT | Problem during reading table feature property. Skipping unknown feature property: msgVersion: 4 objectClass: org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.oxm.rev150225.match.entries.grouping.MatchEntry msgType: 1 oxm_field: 31 experimenterID: null.If more information is needed, set org.opendaylight.openflowjava do DEBUG log level.

And they all fit in a single kara.log file.

If this is all we can do for now we can close this bug.

BR/Luis

Comment by Luis Gomez [ 09/Feb/16 ]

According to Jamo, OPNFV is testing with latest Be and they also find annoying and difficult to debug the controller with so many logs. Really is it not possible to move all these messages to DEBUG level until we do proper implementation in openflowplugin?

Comment by Michal Polkorab [ 09/Feb/16 ]

Setting openflowjava log level to WARN should be enough, shouldn't it ?

Comment by Michal Polkorab [ 09/Feb/16 ]

*specially org.opendaylight.openflowjava.protocol.impl.util

    • to ERROR
Comment by Jamo Luhrsen [ 19/Aug/16 ]

see thread here:

https://lists.opendaylight.org/pipermail/openflowplugin-dev/2016-August/005831.html

also making it critical as I think it makes the user experience pretty poor
when trying to debug other issues in the log.

Comment by Jamo Luhrsen [ 01/Mar/17 ]

(In reply to Jamo Luhrsen from comment #8)
> see thread here:
>
> https://lists.opendaylight.org/pipermail/openflowplugin-dev/2016-August/
> 005831.html
>
> also making it critical as I think it makes the user experience pretty poor
> when trying to debug other issues in the log.

I'm planning to now move our CSIT jobs to set logging levels to ERROR
in order to not see this, but it's still there and really makes a
lot of useless noise when trying to debug other failures.

Comment by Luis Gomez [ 01/Mar/17 ]

I have not seen this issue in Boron/Carbon but it is probably in Beryllium.

Comment by Jamo Luhrsen [ 01/Mar/17 ]

(In reply to Luis Gomez from comment #11)
> I have not seen this issue in Boron/Carbon but it is probably in Beryllium.

https://logs.opendaylight.org/releng/jenkins092/netvirt-csit-1node-openstack-newton-nodl-v2-upstream-learn-carbon/138/archives/odl1_karaf.log.gz

Comment by Luis Gomez [ 01/Mar/17 ]

I do not see this issue in the log you post, it is similar but not the same, just search for "Problem during reading table feature property" that was the issue we had before and now I believe it is fixed. I would probably open a bug for the new issue as it could be just some flow not properly interpreted by ofplugin/ofjava.

Comment by OpenDaylight Release [ 03/May/18 ]

Since the bug is unassigned I'm currently assigning it to you.

Please assign to the relevant person. 

Comment by Luis Gomez [ 03/May/18 ]

This is old stuff, closing.

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