opennetworkinglab / flowvisor

FlowVisor - A network hypervisor
Other
164 stars 67 forks source link

FV crashes when packaging up a large flowstats reply #252

Open jbsbbn opened 11 years ago

jbsbbn commented 11 years ago

I have two datapaths on one VLAN-hybrid HP switch connected to FlowVisor 1.0.10, with two slices, each connected to a separate instance of Floodlight running the staticflowpusher module (one on port 33054 with the FL REST API on 11054, one on 33055 with the FL REST API on 11055). I push in three flows to one of the slices (55), and just over a thousand (1019 if it matters) to the other (54). If I then do

http://localhost:11055/wm/core/switch/all/flow/json

to get flowstats for the one with three flows, it works fine. But if I do

http://localhost:11054/wm/core/switch/all/flow/json

to get flowstats for the one with 1019 flows, FV crashes, saying

Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : MAIN THREAD DIED!!! 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : ---------------------------- 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : ----- exception in thread Thread[main,5,main]::java.nio.BufferOverflowException 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : java.nio.Buffer.nextPutIndex(Buffer.java:512) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : java.nio.DirectByteBuffer.put(DirectByteBuffer.java:263) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.openflow.protocol.OFMatch.writeTo(OFMatch.java:595) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.openflow.protocol.statistics.OFFlowStatisticsReply.writeTo(OFFlowStatisticsReply.java:247) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.openflow.protocol.OFStatisticsMessageBase.writeTo(OFStatisticsMessageBase.java:96) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.openflow.io.OFMessageAsyncStream.appendMessageToOutBuf(OFMessageAsyncStream.java:68) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.openflow.io.OFMessageAsyncStream.write(OFMessageAsyncStream.java:76) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.flowvisor.io.FVMessageAsyncStream.testAndWrite(FVMessageAsyncStream.java:70) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.flowvisor.slicer.FVSlicer.sendMsg(FVSlicer.java:328) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.flowvisor.classifier.FVClassifier.sendFlowStatsResp(FVClassifier.java:1086) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.flowvisor.message.statistics.FVFlowStatisticsReply.classifyFromSwitch(FVFlowStatisticsReply.java:40) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.flowvisor.message.FVStatisticsReply.classifyFromSwitch(FVStatisticsReply.java:30) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.flowvisor.classifier.FVClassifier.classifyOFMessage(FVClassifier.java:551) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.flowvisor.classifier.FVClassifier.handleIOEvent(FVClassifier.java:483) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.flowvisor.classifier.FVClassifier.handleEvent(FVClassifier.java:382) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.flowvisor.events.FVEventLoop.doEventLoop(FVEventLoop.java:168) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.flowvisor.FlowVisor.run(FlowVisor.java:196) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : org.flowvisor.FlowVisor.main(FlowVisor.java:229) 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : ---------------------------- 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: ERROR none : restarting after main thread died 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: WARN classifier-dpid=06:a5:00:24:a8:fe:57:00 : tearing down 
Jul  2 21:51:52 thermopylae -1>Jul  2 21:51:52 flowvisor: WARN classifier-dpid=03:8c:00:24:a8:fe:57:00 : tearing down 
Jul  2 21:51:53 thermopylae -1>Jul  2 21:51:53 flowvisor: INFO none : initializing poll loop 
Jul  2 21:51:53 thermopylae -1>Jul  2 21:51:53 flowvisor: INFO none : initializing FlowVisor UserAPI JSONRPC SSL WebServer on port 8081 
Jul  2 21:51:53 thermopylae -1>Jul  2 21:51:53 flowvisor: INFO OFSwitchAcceptor : Listenning on port 6633 
Jul  2 21:51:53 thermopylae -1>Jul  2 21:51:53 flowvisor: INFO none : initializing FlowVisor UserAPI XMLRPC SSL WebServer on port 8080 
Jul  2 21:51:53 thermopylae -1>Jul  2 21:51:53 flowvisor: FATAL none : failed to spawn APIServer 
Jul  2 21:51:53 thermopylae -1>Jul  2 21:51:53 flowvisor: INFO none : Shutting down config database. 
Jul  2 21:51:53 thermopylae -1>Jul  2 21:51:53 flowvisor: INFO none : Shutting down config database. 

I can reproduce this consistently.

jbsbbn commented 11 years ago

I mentioned this on network-core@geni.net, and Sumanth had some questions. To answer those here, so they're on the ticket:

We saw this in 1.0.10; we haven't tested it in 1.0.8.

I mentioned 64K, and think Nick came up with that number -- I haven't actually checked a lot of variations to see what works and what doesn't. 3 flow rules is fine, I think 250 or so was also fine, more than 1000 causes the crash.

jbsbbn commented 11 years ago

Any ETA on this one? It's a blocker for deploying FV 1.0.x in GENI, which we'd like to announce at GEC 17 that we're going to do after GEC, but we can't with this bug still open. If it can't be fixed by GEC, then it can't -- we just want to plan accordingly.

mssumanth commented 11 years ago

We have the fix for this, which is currently being tested. But the only problem with the tests are that in all our test cases, the Stats_Reply size are of the order of size 20-40 kB since we are testing it using mini net and it would be very hard to get Stats_Reply of the size of MBs

On Fri, Jul 12, 2013 at 8:39 AM, Josh Smift notifications@github.comwrote:

Any ETA on this one? It's a blocker for deploying FV 1.0.x in GENI, which we'd like to announce at GEC 17 that we're going to do after GEC, but we can't with this bug still open. If it can't be fixed by GEC, then it can't -- we just want to plan accordingly.

— Reply to this email directly or view it on GitHubhttps://github.com/OPENNETWORKINGLAB/flowvisor/issues/252#issuecomment-20884438 .

jbsbbn commented 11 years ago

Can you not reproduce it in mininet in the way that I reproduced it in a real switch? (By pushing in a thousand or so flows.)

nbastin commented 11 years ago

This is not fixed - how did you test it? The behaviour is different, but still wrong (now we don't crash flowvisor, it just sends illegal Openflow control packets that cause most controllers to reset).

screen shot 2013-07-27 at 7 31 05 am

What happens here is that a flow stats reply record is cut off in the middle at the end of the packet. The green outlined bytes are a complete flow stats reply, and the red one at the bottom is cut off after 32 bytes (to fit inside the application message size). The packet needs to end after the last complete reply, and may not contain partial replies.

mssumanth commented 11 years ago

The following was my test setup: I started a 200 host , 2 switch mininet topology connected to flowvisor which was connected to floodlight controller. A pingall was done amongst all my hosts(such that when I query for flowstats from any switch would be somewhere between 20 kB and 40kB) and used the floodlight api command to get flow_stats and was able to receive the entire flow_stats reply. During this test, I had set each segment size flow visor sends as a part of flow_stats reply to floodlight to be 512 bytes(since I wasn't able to simulate the flowstats reply record of the order of MB, it was a scaled down version of testing) and was able to receive the entire reply record without flowvisor crashing or floodlight having to reset.

So, the problem you are seeing over here is that inside a segment of a flowstats response record, the last reply is partial which causes the controller to reset. Am I correct in understanding this? Currently, each segment of statsReply is of the length 88*700 = 61600Bytes i.e. slightly less than 64kB and a multiplier of 88 which is the size of the struct ofp_flow_stats_reply according to the OF1.0 spec. Whenever the flowStats reply record exceeds this value, it should append the next set of bytes in the next segment. So I guess, when it is exceeding these many bytes, it is cutting off the last part of the segment. But this should not happen since flowvisor collects all the segments and sends to the controller in one go at the end after all the bytes of all the segments of the flowStats reply record have been collected. So, I do not understand how this partial flow_stats reply is going at the end of the packet.

Some questions: Is this the end of the entire flow_stats reply record or just the end of a particular segment of the flow_stats_reply i.e. does the flow_stats reply continue after this too of were you not able to capture any pcap traces due to the controller reset? Can you please provide me with the entire pcap traces starting from the flow_stats request. Would it be possible to provided the syslogs of flowvisor too during this test?

Thanks & Best Regards Sumanth

nbastin commented 11 years ago

You don't need any hosts at all to test this, nor do you need more than one datapath. We're just testing it with one switch and no hosts - just push down 1000 or so rules into the switch and ask for stats.

As to your questions:

mssumanth commented 11 years ago

Ok, could you please send us the script which you are using to statically push 1000 odd rules.(along with the rules) It will be easy for me to reproduce it over here.

Thanks Sumanth

On Sat, Jul 27, 2013 at 5:06 PM, Nick Bastin notifications@github.comwrote:

You don't need any hosts at all to test this, nor do you need more than one datapath. We're just testing it with one switch and no hosts - just push down 1000 or so rules into the switch and ask for stats.

As to your questions:

  • No idea whether FV would send a continuation (which would be illegal anyhow, and much worse-ly mal-formed), because the connection is reset immediately after TCP reassembly happens on the previous frame
  • I'm not sure how to attach files to github threads (images seem to work fine, but not things github doesn't think are an image) - will send the pcap in an email
  • We don't have the syslogs, although Josh could probably re-create them, but really you should re-creating this in your own test environment otherwise there's no way to know if it's fixed

— Reply to this email directly or view it on GitHubhttps://github.com/OPENNETWORKINGLAB/flowvisor/issues/252#issuecomment-21674709 .

mssumanth commented 11 years ago

How does FV sending a continuation become illegal? When the switch can send FlowStats response with the "MORE_FLAG" set (which specifies that there are more flow stats reply messages coming as part of next segments), FV is doing the same thing over here, just that we are limiting the size(size may be non-standard ) to some value so that the entire big flow_stats instead of going in one huge chunk which resets the TCP connection can go in multiple chunks just as an open flow switch can do!

nbastin commented 11 years ago

If you sent the rest of the flow stats reply that was cut off, that would be completely illegal - you must send fully formed openflow messages in the control channel. Starting your packet with half a flow stats reply is not permitted (nor would a controller know how to parse it). The MORE flag doesn't say "and now there's some fragment of junk coming".

I don't understand how it is not clear that sending 32 bytes of a message after sending a length of 96 is illegal.

mssumanth commented 11 years ago

I understand that sending 32 bytes of a message after sending a length of 96 is illegal. In your first comment you just mentioned a continuation is illegal so I thought you were just referring to the 'next segment itself'. Anyways, if you could send me the 1000 odd flow rules which you used for testing it would be helpful.

Thanks

jbsbbn commented 11 years ago

I've been loading flows with this script:

url=$1 file=$2

while read line do curl -d "$line" $url echo done < $file

The URL is the REST API of the controller, e.g. http://localhost:11054/wm/staticflowentrypusher/json. The file is just a bunch of lines like

{ "switch": "03:8c:00:24:a8:fe:57:00", "name": "IP 10.1.251.1", "ether-type": "0x800", "dst-ip": "10.1.251.1", "active": "true", "actions": "output=72" }

for different destination IP addresses. I've attached a file with a thousand or so of them.

mssumanth commented 11 years ago

The statsReply segment was getting cut because the range of signed shorts is till 32767, and we had assigned each segment of the statsReply to 61600 Bytes. Changed the setting and getting of length of the StatsReply from signed short to unsigned short and the range of each segment of StatsReply to 30800.