Bug 796 - TCP bug in ns-3-dev branch : Crash detected during retesting of Chord on ns-3-dev branch
TCP bug in ns-3-dev branch : Crash detected during retesting of Chord on ns-3...
Status: RESOLVED FIXED
Product: ns-3
Classification: Unclassified
Component: internet
ns-3-dev
Mac Intel Mac OS
: P2 critical
Assigned To: Craig Dowell
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2010-01-20 13:08 EST by Taher Saeed
Modified: 2010-02-13 16:25 EST (History)
3 users (show)

See Also:


Attachments
Logs of the crash for ns-3-dev branch , working logs for ns-3.6 stable release , backtrace (13.07 KB, application/zip)
2010-01-20 13:08 EST, Taher Saeed
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Taher Saeed 2010-01-20 13:08:20 EST
Created attachment 732 [details]
Logs of the crash for ns-3-dev branch , working logs for ns-3.6 stable release , backtrace

Hi,
We were testing our Chord Implementation on the latest ns3-dev release.
We encountered a crash during the below run of the of the program  where the DHASH layer of one node tries to transfer a string to the  DHASH layer of the rightful node over TCP connection.

We noticed that TcpL4Protocol is injecting this payload of 6 bytes in  a supposedly empty packet which
triggers an upcall to the Application layer which leads to a crash.
In the stable release of ns-3.6 (October 21st, 2009) we are able to successfully run the  above scenario.

PFA, the complete logs of the runs in the both the releases as well as the backtrace.


We have found the below piece of debug information delineating the crash.

---------------------------------------------------------------------------
ns-3-dev branch :
---------------------------------------------------------------------------
ChordRun:InsertSuccess()

Current Simulation Time: 1135586200
Insert Success!Bytes: 20
Array: 
[ 0x46 0xe3 0xd7 0x72 0xa1 0x88 0x8e 0xad 0xff 0x26 0xc7 0xad 0xa4 0x7f 0xd7 0x50 0x2d 0x79 0x6e 0x7 ]
Char Array: woods
1.13559e+06 [node 4] TcpSocketImpl 0x101dd0400 adv rxseq by 31
1.13559e+06 [node 1] TcpSocketImpl:SendEmptyPacket(0x101dc0bb0, 16)
1.13559e+06 [node 1] TcpL4Protocol 0x101d49a00 sending seq 32 ack 40 flags 10 data size 0
1.13559e+06 [node 1] TcpL4Protocol:SendPacket(0x101d49a00, 0x102841130, 10.1.1.2, 10.1.1.5, 0)
1.13559e+06 [node 4] TcpL4Protocol:Receive(0x101d4c970, 0x102816a60, 10.1.1.2, 10.1.1.5, 0x101d72260)
ns3::TcpHeader (2002 > 49153 [ ACK ] Seq=32 Ack=40 Win=65535) 
1.13559e+06 [node 4] TcpL4Protocol 0x101d4c970 receiving seq 32 ack 40 flags 10 data size 26
1.13559e+06 [node 4] TcpL4Protocol 0x101d4c970 received a packet
Sending the below packetns3::TcpHeader (2002 > 49153 [ ACK ] Seq=32 Ack=40 Win=65535) Payload (size=6)
1.13559e+06 [node 4] TcpL4Protocol 0x101d4c970 forwarding up to endpoint/socket
1.13559e+06 [node 4] Socket 0x101dd0400 got forward up dport 49153 daddr 10.1.1.5 sport 2002 saddr 10.1.1.2
1.13559e+06 [node 4] TcpSocketImpl:ForwardUp(0x101dd0400, 0x102816a60, 10.1.1.2, 2002)
TcpL4Protocol:FlagsEvent(0x101d77130, )
1.13559e+06 [node 4] TcpSocketImpl:ProcessEvent(0x101dd0400, 6)
1.13559e+06 [node 4] TcpSocketImpl 0x101dd0400 processing event 6
TcpL4Protocol:Lookup(0x101d77130, 4, 6)
1.13559e+06 [node 4] TcpSocketImpl::ProcessEvent stateAction 8
1.13559e+06 [node 4] TcpSocketImpl 0x101dd0400 moved from state 4 to state 4
1.13559e+06 [node 4] TcpSocketImpl 0x101dd0400 pendingData 0
1.13559e+06 [node 4] Socket 0x101dd0400 processing pkt action, 8 current state 4
1.13559e+06 [node 4] TcpSocketImpl:ProcessPacketAction(0x101dd0400, 8, 0x102816a60, 05-06-0a:01:01:02:d2:07)
1.13559e+06 [node 4] TcpSocketImpl 0x101dd0400 Action NEW_ACK_TX
1.13559e+06 [node 4] TcpSocketImpl:ProcessPacketAction(0x101dd0400, 9, 0x102816a60, 05-06-0a:01:01:02:d2:07)
1.13559e+06 [node 4] TcpSocketImpl 0x101dd0400 Action NEW_SEQ_RX
Process packet action.. Calling NewRxPayload (size=6)
1.13559e+06 [node 4] TcpSocketImpl:NewRx(0x101dd0400, 0x102816a60, tcpHeader , 05-06-0a:01:01:02:d2:07)
1.13559e+06 [node 4] TcpSocketImpl 0x101dd0400 NewRx, seq 32 ack 40 p.size is 6
NewRx recieved a packet.Payload (size=6)
1.13559e+06 [node 4] Case 1, advanced nrxs to 38
1.13559e+06 [node 4] TcpSocketImpl:GetRxAvailable()
1.13559e+06 [node 4] TcpSocketImpl:Recv()
1.13559e+06 [node 4] TCP 0x101dd0400 bufferedData.size() 1 time 1135586400137239ns
Payload (size=6)Send empty packet description.DHashConnection::ReadTCPBuffer.Passing the below packet to remove header
Payload (size=6)Removing unexpected header.

Program received signal EXC_BAD_ACCESS, Could not access memory.
Reason: KERN_INVALID_ADDRESS at address: 0x0000000000000000
0x000000010024cb5a in ns3::PacketMetadata::RemoveHeader (this=0x10282d5b0, header=@0x7fff5fbfdfa0, size=4) at ../src/common/packet-metadata.cc:643
643	          NS_FATAL_ERROR ("Removing unexpected header.");

--------------------------------------------------------------------------
ns-3.6 stable release :
--------------------------------------------------------------------------
TcpSocketImpl:CommonNewAck(0x101ab9a50, 1, 1)
TCP 0x101ab9a50 NewAck 1 numberAck 1
TcpSocketImpl:GetTxAvailable()
TcpSocketImpl:GetTxAvailable()
TcpSocketImpl:SendPendingData(0x101ab9a50, 1)
ENTERING SendPendingData
Socket 0x101ab9a50 got forward up dport 2002 daddr 10.1.1.2 sport 49153 saddr 10.1.1.4
TcpSocketImpl:ForwardUp(0x101ab9a50, 0x101ab03b0, 10.1.1.4, 49153)
TcpSocketImpl:ProcessEvent(0x101ab9a50, 6)
TcpSocketImpl 0x101ab9a50 processing event 6
TcpSocketImpl::ProcessEvent stateAction 8
TcpSocketImpl 0x101ab9a50 moved from state 4 to state 4
TcpSocketImpl 0x101ab9a50 pendingData 0
Socket 0x101ab9a50 processing pkt action, 8 current state 4
TcpSocketImpl:ProcessPacketAction(0x101ab9a50, 8, 0x101ab03b0, 05-06-0a:01:01:04:01:c0)
TcpSocketImpl 0x101ab9a50 Action NEW_ACK_TX
TcpSocketImpl:ProcessPacketAction(0x101ab9a50, 9, 0x101ab03b0, 05-06-0a:01:01:04:01:c0)
TcpSocketImpl 0x101ab9a50 Action NEW_SEQ_RX
TcpSocketImpl:NewRx(0x101ab9a50, 0x101ab03b0, tcpHeader , 05-06-0a:01:01:04:01:c0)
TcpSocketImpl 0x101ab9a50 NewRx, seq 1 ack 1 p.size is 39
Case 1, advanced nrxs to 40
TcpSocketImpl:GetRxAvailable()
TcpSocketImpl:Recv()
TCP 0x101ab9a50 bufferedData.size() 1 time 120640200110639ns
TcpSocketImpl:GetTxAvailable()
TcpSocketImpl:GetTxAvailable()
TcpSocketImpl:Send(0x101ab9a50, 0x101ab0410)
TcpSocketImpl:GetTxAvailable()
TcpSock::Send, pdsize 31 state 4
TcpSocketImpl:ProcessEvent(0x101ab9a50, 2)
TcpSocketImpl 0x101ab9a50 processing event 2
TcpSocketImpl::ProcessEvent stateAction 11
TcpSocketImpl 0x101ab9a50 moved from state 4 to state 4
TcpSocketImpl 0x101ab9a50 pendingData 0x101ab9ea0
 action 11
TcpSocketImpl:ProcessAction(0x101ab9a50, 11)
TcpSocketImpl 0x101ab9a50 Action TX_DATA
TcpSocketImpl:SendPendingData(0x101ab9a50, 1)
ENTERING SendPendingData
TcpSocketImpl:AvailableWindow()
TcpSocketImpl:UnAckDataCount()
TcpSocketImpl:Window()
TcpSocketImpl::Window() 0x101ab9a50
TcpSocketImpl 0x101ab9a50 SendPendingData w 536 rxwin 65535 cWnd 536 segsize 536 nextTxSeq 1 highestRxAck 1 pd->Size 31 pd->SFS 31
TcpSocketImpl 0x101ab9a50 SendPendingData txseq 1 s 536 datasize 31
About to send a packet with flags: 
SendPendingData Sent 1 packets
RETURN SendPendingData
TcpSocketImpl 0x101ab9a50 adv rxseq by 39
Socket 0x101ab38d0 got forward up dport 49153 daddr 10.1.1.4 sport 2002 saddr 10.1.1.2
TcpSocketImpl:ForwardUp(0x101ab38d0, 0x101a89ec0, 10.1.1.2, 2002)
TcpSocketImpl:ProcessEvent(0x101ab38d0, 6)
TcpSocketImpl 0x101ab38d0 processing event 6
TcpSocketImpl::ProcessEvent stateAction 8
TcpSocketImpl 0x101ab38d0 moved from state 4 to state 4
TcpSocketImpl 0x101ab38d0 pendingData 0x101ab3b30
Socket 0x101ab38d0 processing pkt action, 8 current state 4
TcpSocketImpl:ProcessPacketAction(0x101ab38d0, 8, 0x101a89ec0, 05-06-0a:01:01:02:d2:07)
TcpSocketImpl 0x101ab38d0 Action NEW_ACK_TX
TcpSocketImpl:NewAck(0x101ab38d0, 40)
TcpSocketImpl 0x101ab38d0 NewAck  seq 40 cWnd 536 ssThresh 65535
TcpSocketImpl 0x101ab38d0 NewCWnd SlowStart, cWnd 1072 sst 65535
TcpSocketImpl:CommonNewAck(0x101ab38d0, 40, 0)
0x101ab38d0 Cancelled ReTxTimeout event which was set to expire at 120643
0x101ab38d0 Schedule ReTxTimeout at time 120640 to expire at time 120640
TCP 0x101ab38d0 NewAck 40 numberAck 39
TcpSocketImpl:GetTxAvailable()
TcpSocketImpl:GetTxAvailable()
0x101ab38d0 Cancelled ReTxTimeout event which was set to expire at 120640
TcpSocketImpl:SendPendingData(0x101ab38d0, 1)
ENTERING SendPendingData
TcpSocketImpl:ProcessPacketAction(0x101ab38d0, 9, 0x101a89ec0, 05-06-0a:01:01:02:d2:07)
TcpSocketImpl 0x101ab38d0 Action NEW_SEQ_RX
TcpSocketImpl:NewRx(0x101ab38d0, 0x101a89ec0, tcpHeader , 05-06-0a:01:01:02:d2:07)
TcpSocketImpl 0x101ab38d0 NewRx, seq 1 ack 40 p.size is 31
Case 1, advanced nrxs to 32
TcpSocketImpl:GetRxAvailable()
TcpSocketImpl:Recv()
TCP 0x101ab38d0 bufferedData.size() 1 time 120640200124319ns
ChordRun:InsertSuccess()


--Regards
Taher
University of Pennsylvania.
Comment 1 Faker Moatamri 2010-01-21 03:49:39 EST
can you please provide your testing parameters and precise command so we can reproduce this behavior??
Thanks
Comment 2 Taher Saeed 2010-01-21 19:40:04 EST
nic770:ns-3-chord taheraquilsaeed$ ./waf --run "examples/chord-run/chord-run 30 1"
Waf: Entering directory `/Users/taheraquilsaeed/ns-3-chord/build'
Waf: Leaving directory `/Users/taheraquilsaeed/ns-3-chord/build'
'build' finished successfully (0.499s)
Number of nodes to simulate: 30
Creating nodes.
Create channels.
Assign IP Addresses.
Create Applications.
ChordRun:Start()
Run Simulation.

Command > 1 InsertVNode N1V1

Command > Processing Command Token...
Scheduling Command InsertVNode...
ChordRun:InsertVNode()

Current Simulation Time: 29596600
Scheduling Command InsertVNode...
ChordRun:JoinSuccess()

Current Simulation Time: 29596600
VNode: N1V1 Joined successfully
Bytes: 20
Array: 
[ 0x4e 0x2c 0x2b 0x1d 0xf0 0x27 0xbe 0xa0 0x5d 0x4c 0xf2 0x4f 0x94 0x84 0xdb 0x10 0x89 0x3b 0xf0 0x23 ]


Command > 2 InsertVNode N2V2

Command > Processing Command Token...
Scheduling Command InsertVNode...
ChordRun:InsertVNode()

Current Simulation Time: 59888000
Scheduling Command InsertVNode...
ChordRun:JoinSuccess()

Current Simulation Time: 59888000
VNode: N2V2 Joined successfully
Bytes: 20
Array: 
[ 0x71 0xdf 0x21 0x49 0x40 0xb0 0xb8 0xc6 0x17 0xe9 0xe6 0xe6 0x97 0x83 0xfc 0xfa 0x74 0x87 0x9a 0xd2 ]
ChordRun:VNodeKeyOwnership()

Current Simulation Time: 59888000
VNode: N1V1 Key Space Ownership change reported
New predecessor Ip: 10.1.1.3 Port: 2001
ChordRun:VNodeKeyOwnership()

Current Simulation Time: 59888000
VNode: N2V2 Key Space Ownership change reported
New predecessor Ip: 10.1.1.2 Port: 2001


Command > 3 InsertVNode N3V3

Command > Processing Command Token...
Scheduling Command InsertVNode...
ChordRun:InsertVNode()

Current Simulation Time: 61210600
Scheduling Command InsertVNode...
ChordRun:JoinSuccess()

Current Simulation Time: 61210600
VNode: N3V3 Joined successfully
Bytes: 20
Array: 
[ 0xe3 0x38 0xab 0x1d 0x28 0x5b 0x84 0xea 0xec 0x20 0xf3 0x9a 0x17 0x8b 0xd2 0xda 0x95 0x44 0xf 0x2b ]
ChordRun:VNodeKeyOwnership()

Current Simulation Time: 61210600
VNode: N2V2 Key Space Ownership change reported
New predecessor Ip: 10.1.1.4 Port: 2001
ChordRun:VNodeKeyOwnership()

Current Simulation Time: 61211000
VNode: N3V3 Key Space Ownership change reported
New predecessor Ip: 10.1.1.2 Port: 2001


Command > 2 Insert tiger woods

Command > Processing Command Token...
Scheduling Command Insert...
ChordRun:Insert()

Current Simulation Time: 61757200
Insert ResourceName : tiger
Insert Resourcevalue : woods
ns3::DHashHeader (Length: 35) ns3::DHashMessage (
***DHashMessage Dump***
Header:: 
MessageType: 1
TransactionId: 0
Payload:: 
StoreReq: 
DHash Object Dump: Bytes: 20
Key: 
[ 0x46 0xe3 0xd7 0x72 0xa1 0x88 0x8e 0xad 0xff 0x26 0xc7 0xad 0xa4 0x7f 0xd7 0x50 0x2d 0x79 0x6e 0x7 ]
Bytes: 5
Object: 
[ 0x77 0x6f 0x6f 0x64 0x73 ]

***End Of Message***
)ns3::DHashHeader (Length: 27) ns3::DHashMessage (
***DHashMessage Dump***
Header:: 
MessageType: 2
TransactionId: 0
Payload:: 
StoreRsp: 
Status: 
Object Identifier: Bytes: 20
Key: 
[ 0x46 0xe3 0xd7 0x72 0xa1 0x88 0x8e 0xad 0xff 0x26 0xc7 0xad 0xa4 0x7f 0xd7 0x50 0x2d 0x79 0x6e 0x7 ]

***End Of Message***
)ChordRun:InsertSuccess()

Current Simulation Time: 61757200
Insert Success!Bytes: 20
Array: 
[ 0x46 0xe3 0xd7 0x72 0xa1 0x88 0x8e 0xad 0xff 0x26 0xc7 0xad 0xa4 0x7f 0xd7 0x50 0x2d 0x79 0x6e 0x7 ]
Char Array: woods
Payload (size=6)Removing unexpected header.
Command ['/Users/taheraquilsaeed/ns-3-chord/build/debug/examples/chord-run/chord-run', '30', '1'] exited with code -11


During the run in the gdb we observe the below packet traces :

Stack while sending empty packet:

#0 0x100379852 in ns3::TcpL4Protocol::SendPacket at tcp-l4-protocol.cc:612
#1 0x1003a308e in ns3::TcpSocketImpl::SendEmptyPacket at tcp-socket-impl.cc:808
#2 0x1003a4312 in ns3::TcpSocketImpl::DelAckTimeout at tcp-socket-impl.cc:1466
#3 0x10039c9b1 in Notify at make-event.h:88
#4 0x10020bb43 in ns3::EventImpl::Invoke at event-impl.cc:37
#5 0x100226ada in ns3::DefaultSimulatorImpl::ProcessOneEvent at default-simulator-impl.cc:117
#6 0x100226b25 in ns3::DefaultSimulatorImpl::Run at default-simulator-impl.cc:147
#7 0x100213ff0 in ns3::Simulator::Run at simulator.cc:173
#8 0x1000094ba in main at chord-run.cc:756


Packet data after adding tcp header:
$1 = {
  m_data = 0x101d9deb0, 
  m_maxZeroAreaStart = 20, 
  m_zeroAreaStart = 20, 
  m_zeroAreaEnd = 20, 
  m_start = 0, 
  m_end = 20
}


Stack while receiving packet (which caused crash):
#0 0x10037a580 in ns3::TcpL4Protocol::Receive at tcp-l4-protocol.cc:489
#1 0x1003640f9 in ns3::Ipv4L3Protocol::LocalDeliver at ipv4-l3-protocol.cc:790
#2 0x100371f05 in ns3::MemPtrCallbackImpl<ns3::Ipv4L3Protocol*, void (ns3::Ipv4L3Protocol::*)(ns3::Ptr<ns3::Packet const>, ns3::Ipv4Header const&, unsigned int), void, ns3::Ptr<ns3::Packet const>, ns3::Ipv4Header const&, unsigned int, ns3::empty, ns3::empty, ns3::empty, ns3::empty, ns3::empty, ns3::empty>::operator() at callback.h:229
#3 0x1004d4f82 in ns3::Callback<void, ns3::Ptr<ns3::Packet const>, ns3::Ipv4Header const&, unsigned int, ns3::empty, ns3::empty, ns3::empty, ns3::empty, ns3::empty, ns3::empty>::operator() at callback.h:416
#4 0x10052e0e5 in ns3::Ipv4ListRouting::RouteInput at ipv4-list-routing.cc:137
#5 0x100365abe in ns3::Ipv4L3Protocol::Receive at ipv4-l3-protocol.cc:483
#6 0x1003721e8 in ns3::MemPtrCallbackImpl<ns3::Ipv4L3Protocol*, void (ns3::Ipv4L3Protocol::*)(ns3::Ptr<ns3::NetDevice>, ns3::Ptr<ns3::Packet const>, unsigned short, ns3::Address const&, ns3::Address const&, ns3::NetDevice::PacketType), void, ns3::Ptr<ns3::NetDevice>, ns3::Ptr<ns3::Packet const>, unsigned short, ns3::Address const&, ns3::Address const&, ns3::NetDevice::PacketType, ns3::empty, ns3::empty, ns3::empty>::operator() at callback.h:238
#7 0x1002e1e87 in ns3::Callback<void, ns3::Ptr<ns3::NetDevice>, ns3::Ptr<ns3::Packet const>, unsigned short, ns3::Address const&, ns3::Address const&, ns3::NetDevice::PacketType, ns3::empty, ns3::empty, ns3::empty>::operator() at callback.h:425
#8 0x1002de031 in ns3::Node::ReceiveFromDevice at node.cc:287
#9 0x1002de2e0 in ns3::Node::NonPromiscReceiveFromDevice at node.cc:261
#10 0x1002e20c1 in ns3::MemPtrCallbackImpl<ns3::Node*, bool (ns3::Node::*)(ns3::Ptr<ns3::NetDevice>, ns3::Ptr<ns3::Packet const>, unsigned short, ns3::Address const&), bool, ns3::Ptr<ns3::NetDevice>, ns3::Ptr<ns3::Packet const>, unsigned short, ns3::Address const&, ns3::empty, ns3::empty, ns3::empty, ns3::empty, ns3::empty>::operator() at callback.h:232
#11 0x100320a18 in ns3::Callback<bool, ns3::Ptr<ns3::NetDevice>, ns3::Ptr<ns3::Packet const>, unsigned short, ns3::Address const&, ns3::empty, ns3::empty, ns3::empty, ns3::empty, ns3::empty>::operator() at callback.h:419
#12 0x1004591cf in ns3::CsmaNetDevice::Receive at csma-net-device.cc:871
#13 0x1004630a9 in Notify at make-event.h:139
#14 0x10020bb43 in ns3::EventImpl::Invoke at event-impl.cc:37
#15 0x100226ada in ns3::DefaultSimulatorImpl::ProcessOneEvent at default-simulator-impl.cc:117
#16 0x100226b25 in ns3::DefaultSimulatorImpl::Run at default-simulator-impl.cc:147
#17 0x100213ff0 in ns3::Simulator::Run at simulator.cc:173
#18 0x1000094ba in main at chord-run.cc:756

Packet data in TcpL4Protocol::Receive (before removing TCP header):
$2 = {
  m_data = 0x101db8880, 
  m_maxZeroAreaStart = 54, 
  m_zeroAreaStart = 54, 
  m_zeroAreaEnd = 54, 
  m_start = 34, 
  m_end = 60
}


I hope this helps.

--Regards
Taher Saeed
Comment 3 Craig Dowell 2010-02-05 20:10:55 EST
Is this bug 806 at work?
Comment 4 Taher Saeed 2010-02-05 20:40:21 EST
Seems the fix for Bug 806 would make this work. I would test the scenario and let you know.
Comment 5 Tom Henderson 2010-02-09 02:03:46 EST
(In reply to comment #4)
> Seems the fix for Bug 806 would make this work. I would test the scenario and
> let you know.

Please close this if the patch for bug 806 (now committed) works.
Comment 6 Taher Saeed 2010-02-13 16:24:52 EST
(In reply to comment #5)
> (In reply to comment #4)
> > Seems the fix for Bug 806 would make this work. I would test the scenario and
> > let you know.
> 
> Please close this if the patch for bug 806 (now committed) works.

This seems to work.Closing this bug.
Thanks a lot for you help.