[CONTROLLER-200] null pointer exception when nodes register with OF1.0/1.3 MD-SAL Created: 07/Mar/14  Updated: 25/Jul/23  Resolved: 15/Apr/14

Status: Resolved
Project: controller
Component/s: mdsal
Affects Version/s: None
Fix Version/s: None

Type: Bug
Reporter: David Bainbridge Assignee: Kamal Rameshan
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Operating System: Mac OS
Platform: Macintosh

External issue ID: 494

 Description   

1. start controller using -of13 switch
2. start mininet with a topo an point it at the controller
3. when nodes register with the controller null pointer exceptions are seen in the log
*. There should never be a null point exception in the log unless there is a real error, so presumably something bad happened somewhere.

2014-03-07 08:36:31.799 PST [nioEventLoopGroup-12-8] INFO o.o.o.p.i.c.PublishingChannelInitializer - Incoming connection from (remote address): /192.168.1.97:50410 --> :6633
2014-03-07 08:36:31.799 PST [nioEventLoopGroup-12-8] INFO o.o.o.p.i.c.PublishingChannelInitializer - Incoming connection accepted - building pipeline
2014-03-07 08:36:31.800 PST [nioEventLoopGroup-12-8] INFO o.o.o.p.i.c.ConnectionAdapterImpl - Hello received / branch
2014-03-07 08:36:31.801 PST [pool-24-thread-2] ERROR o.o.o.o.m.q.TicketProcessorFactory - translation problem: null
2014-03-07 08:36:31.803 PST [Thread-16] ERROR o.o.o.o.md.queue.TicketFinisher - java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at com.google.common.util.concurrent.AbstractFuture$Sync.getValue(AbstractFuture.java:306) ~[na:na]
at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:293) ~[na:na]
at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.queue.TicketFinisher.run(TicketFinisher.java:54) ~[na:na]
at java.lang.Thread.run(Thread.java:744) [na:1.7.0_51]
Caused by: java.lang.NullPointerException: null
at org.opendaylight.openflowplugin.openflow.md.core.translator.ErrorTranslator.translate(ErrorTranslator.java:58) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.core.translator.ErrorTranslator.translate(ErrorTranslator.java:37) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.queue.TicketProcessorFactory$1.translate(TicketProcessorFactory.java:125) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.queue.TicketProcessorFactory$1.run(TicketProcessorFactory.java:80) ~[na:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) ~[na:1.7.0_51]
at java.util.concurrent.FutureTask.run(FutureTask.java:262) ~[na:1.7.0_51]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) ~[na:1.7.0_51]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) ~[na:1.7.0_51]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) ~[na:1.7.0_51]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) ~[na:1.7.0_51]
... 1 common frames omitted

 Comments   
Comment by Hideyuki Tai [ 28/Mar/14 ]

I can reproduce this problem using the latest code.

odp@odp-dev:~/work/openflowplugin$ git log -1
commit fbbab972e5d2f0a489f22ca61931f0da3073ad6c
Author: Michal Rehak <mirehak@cisco.com>
Date: Wed Mar 26 12:21:11 2014 -0700

fix for OPNFLWPLUG-103

  • SalPortService wont be supported for now

Change-Id: Ia9f140d969e324630fbe7d64bd03ff8d198bc0c5
Signed-off-by: Michal Rehak <mirehak@cisco.com>

The following messages appeared in OSGi console.

2014-03-28 14:52:24.542 EDT [nioEventLoopGroup-9-3] INFO o.o.o.p.i.c.ConnectionAdapterImpl - Hello received / branch
2014-03-28 14:52:24.543 EDT [pool-22-thread-3] ERROR o.o.o.o.m.q.TicketProcessorFactory - translation problem: null
2014-03-28 14:52:24.545 EDT [Thread-13] ERROR o.o.o.o.md.queue.TicketFinisher - java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at com.google.common.util.concurrent.AbstractFuture$Sync.getValue(AbstractFuture.java:306) ~[na:na]
at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:293) ~[na:na]
at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.queue.TicketFinisher.run(TicketFinisher.java:54) ~[na:na]
at java.lang.Thread.run(Thread.java:722) [na:1.7.0_15]
Caused by: java.lang.NullPointerException: null
at org.opendaylight.openflowplugin.openflow.md.core.translator.AbstractErrorTranslator.translate(AbstractErrorTranslator.java:63) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.core.translator.AbstractErrorTranslator.translate(AbstractErrorTranslator.java:36) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.queue.TicketProcessorFactory$1.translate(TicketProcessorFactory.java:125) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.queue.TicketProcessorFactory$1.run(TicketProcessorFactory.java:80) ~[na:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) ~[na:1.7.0_15]
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) ~[na:1.7.0_15]
at java.util.concurrent.FutureTask.run(FutureTask.java:166) ~[na:1.7.0_15]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) ~[na:1.7.0_15]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) ~[na:1.7.0_15]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) ~[na:1.7.0_15]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) ~[na:1.7.0_15]
... 1 common frames omitted
2014-03-28 14:52:24.562 EDT [md-sal-binding-commit-0] WARN o.o.c.m.s.manager.StatisticsProvider - Attempted to start already-existing handler for Uri [_value=openflow:1], very strange

Comment by Kamal Rameshan [ 28/Mar/14 ]

1. Rebased the latest controller, openflowplugin and openflowjava.

2. Ran the controller from openflowplugin/distribution with the -of13 option

3. Started mininet with tree topo
sudo mn --controller=remote,ip=192.168.56.1 --top=tree,2 --switch ovsk,protocols=OpenFlow13

4. No NPE errors were found when the nodes registered

Works for me. Assigning it back as i cannot reproduce.

Comment by Vaishali Mithbaokar [ 31/Mar/14 ]

This bug is unreproducible, see details below from Kamal Rameshan
1. Rebased the latest controller, openflowplugin and openflowjava.

2. Ran the controller from openflowplugin/distribution with the -of13 option

3. Started mininet with tree topo
sudo mn --controller=remote,ip=192.168.56.1 --top=tree,2 --switch ovsk,protocols=OpenFlow13

4. No NPE errors were found when the nodes registered

Waiting for submitter , David Bainbridge , to verify that this bug doesnt exist with latest code

Comment by Kamal Rameshan [ 01/Apr/14 ]

Verified with Michal Rehak (of OF) as well, and he said he was also not able to reproduce.

On email, communicated with David and he said he will verify after his trip from Haiti

Thx
Kamal

Comment by Hideyuki Tai [ 15/Apr/14 ]

I can reproduce this issue with the latest code when I run mininet in OF 1.0 mode.

I pulled the latest code of the Integration Git repository, and built the base edition.
I started the base edition with "-of13" option, and run mininet using OF 1.0.
When OF nodes registered on the controller, the following ERROR messages appeared in OSGi console.

2014-04-14 22:51:34.102 EDT [Thread-17] ERROR o.o.o.o.md.queue.TicketFinisher - java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
at com.google.common.util.concurrent.AbstractFuture$Sync.getValue(AbstractFuture.java:306) ~[na:na]
at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:293) ~[na:na]
at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:116) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.queue.TicketFinisher.run(TicketFinisher.java:54) ~[na:na]
at java.lang.Thread.run(Thread.java:722) [na:1.7.0_15]
Caused by: java.lang.NullPointerException: null
at org.opendaylight.openflowplugin.openflow.md.core.translator.AbstractErrorTranslator.translate(AbstractErrorTranslator.java:63) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.core.translator.AbstractErrorTranslator.translate(AbstractErrorTranslator.java:36) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.queue.TicketProcessorFactory$1.translate(TicketProcessorFactory.java:125) ~[na:na]
at org.opendaylight.openflowplugin.openflow.md.queue.TicketProcessorFactory$1.run(TicketProcessorFactory.java:80) ~[na:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) ~[na:1.7.0_15]
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) ~[na:1.7.0_15]
at java.util.concurrent.FutureTask.run(FutureTask.java:166) ~[na:1.7.0_15]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:178) ~[na:1.7.0_15]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:292) ~[na:1.7.0_15]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) ~[na:1.7.0_15]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) ~[na:1.7.0_15]
... 1 common frames omitted

[Operation for mininet]
mininet@mininet-vm:~$ mn --version
2.0.0
mininet@mininet-vm:~$ sudo mn --controller=remote,ip=192.168.60.180 --topo tree,3

[Operation for OpenDaylight Controller]

$ git log -1
commit e4ecb6d69d0d7b6b7566fa184386866fb05ae3e1
Author: Robert Varga <rovarga@cisco.com>
Date: Fri Apr 11 17:20:51 2014 +0200

Do not bundle META-INF in configuration

This fixes a packaging issue, where the META-INF directory of
downstream configuration jars would be included in final distribution's
configuration directory – e.g. we had a useless configuration/META-INF
directory.

Should be included in stable branch, too.

Change-Id: I96ad12589876d2585dab5cd3ddee4e271fbb3231
Signed-off-by: Robert Varga <rovarga@cisco.com>

$ ./run.sh -of13

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