[OPNFLWJAVA-29] Null pointer exceptions when multiple concurrent restconf client attempting to program flows Created: 16/Jul/14  Updated: 18/Jul/14  Resolved: 18/Jul/14

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

Type: Bug
Reporter: Jan Medved Assignee: Jan Medved
Resolution: Done 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: 1373

 Description   

I get a lot of null pointer exceptions when more than restconf client tries to program flows. See attached logs

To reproduce:
1. connect mininet to the controller
2. start the below pything script with the following command line:
python flow_config_perf.py --nflows 20 --nthreads 2

The test Python script below this line
----------------------------------

from random import randrange
import json
import argparse
import requests
import time
import threading

class Counter(object):
def _init_(self, start=0):
self.lock = threading.Lock()
self.value = start
def increment(self, value=1):
self.lock.acquire()
try:
self.value = self.value + value
finally:
self.lock.release()

class Timer(object):
def _init_(self, verbose=False):
self.verbose = verbose

def _enter_(self):
self.start = time.time()
return self

def _exit_(self, *args):
self.end = time.time()
self.secs = self.end - self.start
self.msecs = self.secs * 1000 # millisecs
if self.verbose:
print ("elapsed time: %f ms" % self.msecs)

putheaders =

{'content-type': 'application/json'}

getheaders =

{'Accept': 'application/json'}
  1. ODL IP:port
  2. We fist delete all existing service functions
    DELURL = "restconf/config/opendaylight-inventory:nodes/node/openflow:%d/table/0/flow/%d"
    GETURL = "restconf/config/opendaylight-inventory:nodes/node/openflow:%d/table/0/flow/%d"
  3. Incremental PUT. This URL is for a list element
    PUTURL = "restconf/config/opendaylight-inventory:nodes/node/openflow:%d/table/0/flow/%d"

INVURL = 'restconf/operational/opendaylight-inventory:nodes'
N1T0_URL = 'restconf/operational/opendaylight-inventory:nodes/node/openflow:1/table/0'

print_lock = threading.Lock()

JSON_FLOW_MOD1 = '''{
"flow-node-inventory:flow": [
{
"flow-node-inventory:cookie": %d,
"flow-node-inventory:cookie_mask": 65535,
"flow-node-inventory:flow-name": "%s",
"flow-node-inventory:hard-timeout": %d,
"flow-node-inventory:id": "%s",
"flow-node-inventory:idle-timeout": %d,
"flow-node-inventory:installHw": false,
"flow-node-inventory:instructions": {
"flow-node-inventory:instruction": [
{
"flow-node-inventory:apply-actions": {
"flow-node-inventory:action": [
{
"flow-node-inventory:dec-nw-ttl": {},
"flow-node-inventory:order": 0
}
]
},
"flow-node-inventory:order": 0
}
]
},
"flow-node-inventory:match": {
"flow-node-inventory:metadata":

{ "flow-node-inventory:metadata": %d }

},
"flow-node-inventory:priority": 2,
"flow-node-inventory:strict": false,
"flow-node-inventory:table_id": 0
}
]
}'''

add_ok_rate = Counter(0.0)
add_total_rate = Counter(0.0)
del_ok_rate = Counter(0.0)
del_total_rate = Counter(0.0)

def add_flow(url_template, s, res, tid, node, flow_id, metadata):
flow_data = JSON_FLOW_MOD1 % (tid + flow_id, 'TestFlow-%d' % flow_id, 3400,
str(flow_id), 1200, metadata)
flow_url = url_template % (node, flow_id)
r = s.put(flow_url, data=flow_data, headers=putheaders, stream=False )

try:
res[r.status_code] += 1
except(KeyError):
res[r.status_code] = 1

def delete_flow(url_template, s, res, tid, node, flow_id):
flow_url = url_template % (node, flow_id)
r = s.delete(flow_url, headers=getheaders)
try:
res[r.status_code] += 1
except(KeyError):
res[r.status_code] = 1

def get_num_nodes(inventory_url, s, default_nodes):
nodes = default_nodes
r = s.get(inventory_url, headers=getheaders, stream=False )
if (r.status_code == 200):
try:
inv = json.loads(r.content)['nodes']['node']
nodes = len(inv)
except(KeyError):
pass

return nodes

def add_delete_flows(put_url, del_url, nnodes, nflows, tid, cond):
add_res = {}
del_res = {}
flows = {}

s = requests.Session()
nnodes = get_num_nodes(inv_url, s, nnodes)

with print_lock:
print 'Thread %d: Adding %d flows on %d nodes' % (tid, nflows, nnodes)

with Timer() as t:
for flow in range(nflows):
node_id = randrange(nnodes)
flow_id = tid*100000 + flow
flows[flow_id] = node_id
add_flow(put_url, s, add_res, tid, node_id, flow_id, flow*2+1)

add_time = t.secs

with print_lock:
print 'Thread %d: Deleting %d flows on %d nodes' % (tid, nflows, nnodes)

with Timer() as t:
for flow in range(nflows):
flow_id = tid*100000 + flow
delete_flow(del_url, s, del_res, 100, flows[flow_id], flow_id)

del_time = t.secs

add_ok_rate_t = add_res[200]/add_time
add_total_rate_t = sum(add_res.values())/add_time

add_ok_rate.increment(add_ok_rate_t)
add_total_rate.increment(add_total_rate_t)

del_ok_rate_t = del_res[200]/del_time
del_total_rate_t = sum(del_res.values())/del_time

del_ok_rate.increment(del_ok_rate_t)
del_total_rate.increment(del_total_rate_t)

with print_lock:
print '\nThread %d: ' % tid
print ' Add time: %.2f,' % add_time
print ' Add success rate: %.2f, Add total rate: %.2f' % \
(add_ok_rate_t, add_total_rate_t)
print ' Add Results: ',
print add_res
print ' Delete time: %.2f,' % del_time
print ' Delete success rate: %.2f, Delete total rate: %.2f' % \
(del_ok_rate_t, del_total_rate_t)
print ' Delete Results: ',
print del_res

with cond:
cond.notifyAll()

if _name_ == "_main_":
parser = argparse.ArgumentParser(description='Restconf test program')
parser.add_argument('--odlhost', default='127.0.0.1', help='host where '
'odl controller is running (default is 127.0.0.1)')
parser.add_argument('--odlport', default='8080', help='port on '
'which odl\'s RESTCONF is listening (default is 8080)')
parser.add_argument('--nflows', type=int, default=10, help='number of '
'flow add/delete cycles to send in each thread; default 10')
parser.add_argument('--nthreads', type=int, default=1,
help='Number of request worker threads, default=1')
parser.add_argument('--nnodes', type=int, default=16,
help='Number of nodes if mininet not connected, default=16')

in_args = parser.parse_args()

put_url = 'http://' + in_args.odlhost + ":" + in_args.odlport + '/' + PUTURL
del_url = 'http://' + in_args.odlhost + ":" + in_args.odlport + '/' + DELURL
get_url = 'http://' + in_args.odlhost + ":" + in_args.odlport + '/' + GETURL
inv_url = 'http://' + in_args.odlhost + ":" + in_args.odlport + '/' + INVURL

nnodes = in_args.nnodes
nflows = in_args.nflows

cond = threading.Condition()
threads = []
nthreads = in_args.nthreads

for i in range(nthreads):
t = threading.Thread(target=add_delete_flows,
args=(put_url, del_url, nnodes, nflows, i, cond))
threads.append(t)
t.start()

finished = 0
while finished < nthreads:
with cond:
cond.wait()
finished = finished + 1

print '\n Overall add success rate: %.2f, Overall add rate: %.2f' % \
(add_ok_rate.value, add_total_rate.value)
print ' Overall delete success rate: %.2f, Overall delete rate: %.2f' % \
(del_ok_rate.value, del_total_rate.value)



 Comments   
Comment by Jan Medved [ 16/Jul/14 ]

Web Access log:
2014-07-15 23:01:21.807 PDT - [127.0.0.1] - GET /restconf/operational/opendaylight-inventory:nodes HTTP/1.1
2014-07-15 23:01:21.996 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/0 HTTP/1.1
2014-07-15 23:01:22.012 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:15/table/0/flow/1 HTTP/1.1
2014-07-15 23:01:22.028 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:7/table/0/flow/2 HTTP/1.1
2014-07-15 23:01:22.043 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/3 HTTP/1.1
2014-07-15 23:01:22.058 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:1/table/0/flow/4 HTTP/1.1
2014-07-15 23:01:22.072 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/5 HTTP/1.1
2014-07-15 23:01:22.085 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/6 HTTP/1.1
2014-07-15 23:01:22.102 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:8/table/0/flow/7 HTTP/1.1
2014-07-15 23:01:22.118 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:14/table/0/flow/8 HTTP/1.1
2014-07-15 23:01:22.133 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:8/table/0/flow/9 HTTP/1.1
2014-07-15 23:01:22.147 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:13/table/0/flow/10 HTTP/1.1
2014-07-15 23:01:22.160 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:9/table/0/flow/11 HTTP/1.1
2014-07-15 23:01:22.175 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:10/table/0/flow/12 HTTP/1.1
2014-07-15 23:01:22.185 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:8/table/0/flow/13 HTTP/1.1
2014-07-15 23:01:22.199 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:15/table/0/flow/14 HTTP/1.1
2014-07-15 23:01:22.215 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:14/table/0/flow/15 HTTP/1.1
2014-07-15 23:01:22.226 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:11/table/0/flow/16 HTTP/1.1
2014-07-15 23:01:22.240 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/17 HTTP/1.1
2014-07-15 23:01:22.252 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:9/table/0/flow/18 HTTP/1.1
2014-07-15 23:01:22.267 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/19 HTTP/1.1
2014-07-15 23:01:22.284 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/0 HTTP/1.1
2014-07-15 23:01:22.294 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:15/table/0/flow/1 HTTP/1.1
2014-07-15 23:01:22.303 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:7/table/0/flow/2 HTTP/1.1
2014-07-15 23:01:22.313 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/3 HTTP/1.1
2014-07-15 23:01:22.322 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:1/table/0/flow/4 HTTP/1.1
2014-07-15 23:01:22.329 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/5 HTTP/1.1
2014-07-15 23:01:22.337 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/6 HTTP/1.1
2014-07-15 23:01:22.346 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:8/table/0/flow/7 HTTP/1.1
2014-07-15 23:01:22.356 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:14/table/0/flow/8 HTTP/1.1
2014-07-15 23:01:22.364 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:8/table/0/flow/9 HTTP/1.1
2014-07-15 23:01:22.371 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:13/table/0/flow/10 HTTP/1.1
2014-07-15 23:01:22.380 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:9/table/0/flow/11 HTTP/1.1
2014-07-15 23:01:22.387 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:10/table/0/flow/12 HTTP/1.1
2014-07-15 23:01:22.396 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:8/table/0/flow/13 HTTP/1.1
2014-07-15 23:01:22.404 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:15/table/0/flow/14 HTTP/1.1
2014-07-15 23:01:22.413 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:14/table/0/flow/15 HTTP/1.1
2014-07-15 23:01:22.422 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:11/table/0/flow/16 HTTP/1.1
2014-07-15 23:01:22.430 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/17 HTTP/1.1
2014-07-15 23:01:22.438 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:9/table/0/flow/18 HTTP/1.1
2014-07-15 23:01:22.445 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/19 HTTP/1.1
2014-07-15 23:02:06.803 PDT - [127.0.0.1] - GET /restconf/operational/opendaylight-inventory:nodes HTTP/1.1
2014-07-15 23:02:06.836 PDT - [127.0.0.1] - GET /restconf/operational/opendaylight-inventory:nodes HTTP/1.1
2014-07-15 23:02:06.855 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/100000 HTTP/1.1
2014-07-15 23:02:06.865 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/0 HTTP/1.1
2014-07-15 23:02:06.893 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:1/table/0/flow/100001 HTTP/1.1
2014-07-15 23:02:06.910 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/1 HTTP/1.1
2014-07-15 23:02:06.933 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/100002 HTTP/1.1
2014-07-15 23:02:06.966 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/2 HTTP/1.1
2014-07-15 23:02:06.986 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/100003 HTTP/1.1
2014-07-15 23:02:07.009 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/3 HTTP/1.1
2014-07-15 23:02:07.036 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/100004 HTTP/1.1
2014-07-15 23:02:07.206 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/4 HTTP/1.1
2014-07-15 23:02:07.216 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/100005 HTTP/1.1
2014-07-15 23:02:07.221 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/5 HTTP/1.1
2014-07-15 23:02:07.235 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/100006 HTTP/1.1
2014-07-15 23:02:07.248 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/6 HTTP/1.1
2014-07-15 23:02:07.258 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/100007 HTTP/1.1
2014-07-15 23:02:07.283 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/7 HTTP/1.1
2014-07-15 23:02:07.297 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/100008 HTTP/1.1
2014-07-15 23:02:07.306 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/8 HTTP/1.1
2014-07-15 23:02:07.313 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/100009 HTTP/1.1
2014-07-15 23:02:07.328 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/9 HTTP/1.1
2014-07-15 23:02:07.343 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/100010 HTTP/1.1
2014-07-15 23:02:07.352 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/10 HTTP/1.1
2014-07-15 23:02:07.360 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/100011 HTTP/1.1
2014-07-15 23:02:07.368 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:1/table/0/flow/11 HTTP/1.1
2014-07-15 23:02:07.375 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/100012 HTTP/1.1
2014-07-15 23:02:07.415 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/12 HTTP/1.1
2014-07-15 23:02:07.423 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/100013 HTTP/1.1
2014-07-15 23:02:07.429 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:1/table/0/flow/13 HTTP/1.1
2014-07-15 23:02:07.439 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/100014 HTTP/1.1
2014-07-15 23:02:07.473 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/14 HTTP/1.1
2014-07-15 23:02:07.481 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/100015 HTTP/1.1
2014-07-15 23:02:07.492 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/15 HTTP/1.1
2014-07-15 23:02:07.501 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/100016 HTTP/1.1
2014-07-15 23:02:07.507 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/16 HTTP/1.1
2014-07-15 23:02:07.566 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/100017 HTTP/1.1
2014-07-15 23:02:07.571 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/17 HTTP/1.1
2014-07-15 23:02:07.604 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/100018 HTTP/1.1
2014-07-15 23:02:07.611 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/18 HTTP/1.1
2014-07-15 23:02:07.640 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/100019 HTTP/1.1
2014-07-15 23:02:07.648 PDT - [127.0.0.1] - PUT /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/19 HTTP/1.1
2014-07-15 23:02:07.670 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/100000 HTTP/1.1
2014-07-15 23:02:07.688 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/0 HTTP/1.1
2014-07-15 23:02:07.697 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:1/table/0/flow/100001 HTTP/1.1
2014-07-15 23:02:07.717 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/1 HTTP/1.1
2014-07-15 23:02:07.731 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/100002 HTTP/1.1
2014-07-15 23:02:07.745 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/2 HTTP/1.1
2014-07-15 23:02:07.762 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/100003 HTTP/1.1
2014-07-15 23:02:07.777 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/3 HTTP/1.1
2014-07-15 23:02:07.791 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/100004 HTTP/1.1
2014-07-15 23:02:07.965 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/4 HTTP/1.1
2014-07-15 23:02:07.979 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/100005 HTTP/1.1
2014-07-15 23:02:07.985 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/5 HTTP/1.1
2014-07-15 23:02:08.009 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/100006 HTTP/1.1
2014-07-15 23:02:08.014 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/6 HTTP/1.1
2014-07-15 23:02:08.038 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/100007 HTTP/1.1
2014-07-15 23:02:08.064 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/7 HTTP/1.1
2014-07-15 23:02:08.077 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/100008 HTTP/1.1
2014-07-15 23:02:08.083 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/8 HTTP/1.1
2014-07-15 23:02:08.106 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/100009 HTTP/1.1
2014-07-15 23:02:08.111 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/9 HTTP/1.1
2014-07-15 23:02:08.135 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/100010 HTTP/1.1
2014-07-15 23:02:08.141 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/10 HTTP/1.1
2014-07-15 23:02:08.165 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/100011 HTTP/1.1
2014-07-15 23:02:08.170 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:1/table/0/flow/11 HTTP/1.1
2014-07-15 23:02:08.194 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/100012 HTTP/1.1
2014-07-15 23:02:08.219 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/12 HTTP/1.1
2014-07-15 23:02:08.236 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:4/table/0/flow/100013 HTTP/1.1
2014-07-15 23:02:08.242 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:1/table/0/flow/13 HTTP/1.1
2014-07-15 23:02:08.265 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/100014 HTTP/1.1
2014-07-15 23:02:08.292 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/14 HTTP/1.1
2014-07-15 23:02:08.306 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/100015 HTTP/1.1
2014-07-15 23:02:08.311 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/15 HTTP/1.1
2014-07-15 23:02:08.335 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:2/table/0/flow/100016 HTTP/1.1
2014-07-15 23:02:08.341 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:5/table/0/flow/16 HTTP/1.1
2014-07-15 23:02:08.384 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/100017 HTTP/1.1
2014-07-15 23:02:08.555 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:3/table/0/flow/17 HTTP/1.1
2014-07-15 23:02:08.598 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/100018 HTTP/1.1
2014-07-15 23:02:08.606 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/18 HTTP/1.1
2014-07-15 23:02:08.650 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:0/table/0/flow/100019 HTTP/1.1
2014-07-15 23:02:08.657 PDT - [127.0.0.1] - DELETE /restconf/config/opendaylight-inventory:nodes/node/openflow:6/table/0/flow/19 HTTP/1.1

Comment by Jan Medved [ 16/Jul/14 ]

Note that the null pointer exceptions (missing serializer, etc.) do not occur when only one thread add/deletes flows.

Comment by Michal Polkorab [ 16/Jul/14 ]

I am unable to reproduce this issue. Tried with different mininet topologies, different number of thread and flows used. There are no ofjava logs after connection is established. I can see only exceptions (probably) related to CONTROLLER-630.

Can you paste some of those missing serializer logs, please ?

Comment by Jan Medved [ 16/Jul/14 ]

You have all the logs attached to a private email.

Comment by Michal Polkorab [ 16/Jul/14 ]

Pasting one of NullPointerExceptions:

2014-07-15 23:02:06.857 PDT [nioEventLoopGroup-11-1] ERROR o.o.o.protocol.impl.core.OFEncoder - Serializer for key: msgVersion: 1 msgType: org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.common.action.rev130731.actions.grouping.Action msgType2: org.opendaylight.yang.gen.v1.urn.opendaylight.openflow.common.action.rev130731.DecNwTtl was not found

The NullPointerException for missing serializer is correct. There is no DecNwTtl action in OF 1.0.

The message might have been translated incorrectly (outside the OFjava) or you might be trying to use this action with an OF 1.0 device (maybe cbench ?).

Comment by Tony Tkacik [ 16/Jul/14 ]

Michal then log report should be different, you should throw NullPointer when
client input is null, in your case it is IllegalArgumentException. Maybe rewording
will be much more helful such as DecNwTlw is not supported for Openflow version 0x01.

Comment by Jan Medved [ 16/Jul/14 ]

The illegal state exceptions are still there, even if i use OF1.3 mininet. The rates did not change much

Comment by Michal Polkorab [ 17/Jul/14 ]

Issue should be fixed by this change:
https://git.opendaylight.org/gerrit/#/c/9115/

Please verify.

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