Receiver is not recovering lost Data blk>0 seg>1

[marygilliland]

I have a test case where my receiving application often misses the first message sent by the sending application. Both applications are using the NORM API in the NORM_OBJECT_STREAM mode.

I’m using the linux traffic control to create random packet losses of 5% on the network interface used by the sending application.

I start my receiving application and wait for it to indicate that it is blocking, waiting to receive the first message from the sending application. Then I start the sending application. In my test case, a total of 50 messages are sent.

It seems that if any message other than the first message (DATA obj>0 blk>0 seg>1) is affected by the network losses, the NORM NACKing protocol works as expected to deliver all 50 messages to the receiving application. Looking at the trace/debug file where the receiving application does not get the first message, I can see that the receiving application did not receive the first “DATA obj” packet sent by the sending application (DATA obj>0 blk>0 seg>1). I can see the receiving application send a NACK packet, and the sending application responds with the requested “DATA obj”. But on the receiving side, these messages are shown in the trace/debug file, and it seems that the message is discarded rather than being passed up to the application layer.

trace>20:12:53.031043 node>1355305018 src>172.27.1.60/56330 inst>40430 seq>30 DATA obj>0 blk>0 seg>0 offset>0 len>117
Proto Debug: NormStreamObject::WriteSegment() block/segment < read_index!?
Proto Debug: NormObject::HandleObjectMessage() WriteSegment() error
Proto Debug: NormSenderNode::RepairCheck() node>1355305018 sender rewind detected, ending NACK holdoff ...

I’m attaching the full trace/debug files for the sender and the receiver. I’m also attaching the source code I’m using to set up a socket to send, a socket to receive, and for the event handling. We have configuration for setting some of the NORM control parameters, so I provided the values we are using in this test case as comments.

In the initial observations of this scenario, I had the TxRobustFactor set to 5, to reduce the “chattiness”. We had done quite a bit of testing with that setting, and had not observed anything unexpected. It’s only during the last month of testing that we’ve run into this scenario. So, I put the TxRobustFactor back to the default of 20. But that has not made any difference in the scenario.

I do have the sync policy set to NORM_SYNC_CURRENT. I have considered that maybe NORM_SYNC_ALL would be required to address the scenario I’m seeing with the lost first message. However, I would not want a receiver that “joined the party late” to use NACKing to receive previous messages. For instance, if a receiver didn’t start until after the 10th message had been sent, so the first message it saw was the 11th message, I would not want it to use NACKing to receive the first 10 messages.

I hope there is a way to distinguish between the “receiver was running when a lost message was sent, so recover it”, versus the “receiver was not running when that message was sent, so don’t recover it”.

Hoping for some advice on how to handle this situation.

Thanks.

SenderLog230430.txt
NORMProjectSource.txt
ReceiverLog230430.txt

[bebopagogo]

The “NORM sync policy” does control the behavior you describe here. The basic “SYNC_CURRENT” policy for DATA/FILE objects is for the receiver to wait until it sees a NORM_DATA message from the first FEC block of one of those objects before “syncing” and beginning sending repair requests (NACKs) for any content. Once a receiver syncs, it is then pretty tenacious, but the reason for that policy is to avoid having late joining receivers penalize the forward progress of the group. For STREAM objects, this policy is augmented by having the first received NORM_DATA packet be uses as the “sync index” and NORM shouldn’t NACK for stream data earlier than that index under the SYNC_CURRENT policy. However, the behavior you observe actually indicates there may be an inconsistency in the code in that regards. I can’t recall if I intended to set the index according to the index of the NORM_DATA packet received or according to first segment of the first FEC block received.

From the behavior describe it seems that the “repair check” is sending a NACK as if the index was set to segment zero of the first received FEC block id, but the receiver stream index is set according to that received packet block/segment id and so it discards the retransmitted packet since it’s ordinally lower than the stream sync block/segment id. The sync policy option is something specific to my implementation and the behavior is not defined in the NORM RFC. Probably, the intended behavior was to sync on a block basis, but one of the issues with NORM for very high speed applications is the sort of sloppy behavior that can happen with a bunch of receivers asynchronously joining the group due to the NACKing/retransmission is problematic when something like the ACK-based flow control is not used (as an aside: the “NormSocket” API extension provides a more connection-oriented paradigm which could be used for oore organized behaviors since the receivers have backchannel to the sender app, etc and it also has the ACK-based flow control embedded into it). In any case – I need to look into this. I will need to do that carefully so I don’t break anything, but possibly doing the stream sync on an FEC block basis might give you the desired behavior and be an appropriate solution for general “SYNC_CURRENT” utility. The potentially problematic aspect of this should probably be just addressed by using flow control properly.

The SYNC_ALL policy enables late-joining receivers (or a receiver that misses the first packet of a stream) to send NACKs requesting transmission of any content the sender has buffered. This is useful for applications that have receivers that don’t want to miss any data and is a little more like a TCP connection in this regard. If your application generally has receivers starting close the beginning of the sender transmission, this sync mode is useful. If you have receivers that join late/mid-stream, then this mode will cause the sender to retransmit older data. However, that is limited by the NORM “stream buffer” size your sender application sets when it opens a stream object. So, if your stream buffer is not too large, this may not be a large penalty?

Note there is also a SYNC_STREAM mode. This one is for the case where an application serializes a sequence of different/multiple stream objects or mix of object types and wants to allow receivers to request repair to the beginning of a current stream but not for earlier stream objects. I haven’t personally tried this, but you potentially could have your sender break up its transmission into a series of stream objects using this policy. This could limit the utility of the NORM FEC-based repair strategy for multicast if your stream objects were small in size (limited FEC blocks). It would be a little more complex use of the API to manage the series of stream objects enqueued and the code has not really been tested with this use pattern.

So, to summarize:

I will investigate if the SYNC_CURRENT policy should do its sync based on FEC block boundaries (note if you FEC block size is zero, you will have the same behavior you are seeing except for the wasted NACK/retransmission behavior you are seeing). If your application allows late-joining receivers to join mid-stream, I’m not sure exactly what your concern here is with respect to a “a little bit late” versus “a lot late” ? 😉.
SYNC_ALL may be an appropriate policy. Or SYNC_STREAM …

Hopefully this is helpful. I sort of understand what you mean by receiver was running versus not when the loss occurred. I guess that assumes the receiver is started with some knowledge of when the sender is started? If you have that info, you could have those receiver use SYNC_ALL while late joining receivers use SYNC_CURRENT …

Again in either case, a receiver shouldn’t NACK for something it sends up throwing away because of some inconsistency in the sync policy implementation and I will look into that.

[bebopagogo]

I looked at the code and for the SYNC_CURRENT policy, the received NORM_DATA message its FEC block id and segment id zero is used to set the starting point for purposes of NACKing but the stream "read_index" that marks the current index from where the application begins "reading" data uses the received segment id (instead of segment id zero). If I can safely change the code so that read_index is set using the FEC block id and segment_id zero, then the retransmitted message in your debug log here would not be discarded. I need to spend some time reacquainting myself with the associated code here to make sure I can make a good fix that doesn't cause some other issue.

[marygilliland]

Thanks for the updates. Will be on the lookout for that code change. I also have some more log files to post, showing some other cases that seem to be unique from this situation.

[bebopagogo]

Are those other logfiles consistent with the sync policy behavior described here? I spent a little more time and I think the change to have SYNC_CURRENT sync up on an FEC block basis will be not too difficult but need to make the change and test. Note that if your receiver misses an entire FEC block of packets at start, the sync up will be on whatever subsequent block for which it first receives a packet. Another thing for me to look at is if it is useful to allow for sync on receipt of a NORM_CMD(FLUSH) message that includes the current/last block id the sender has transmitted.

[marygilliland]

This pair of log files relates to different applications than the first pair of log files related to. This pair of log files relates to a subsystem of applications that use multicast to exchange messages about events. The subsystem consists of 9 unique applications (multiple instances of each can be running) multicasting on 8 different ports. Each application opens multiple sockets, some for receiving and some for sending. The examples I will point out relate to only one port, with the log files from one sender and one receiver. We ran a test in which we expected to record 700 events, and we missed 33. We had 5% induced network packet losses. Any given event may involve the exchange of multiple messages; so don’t assume that 33 missed events equates to 33 missed messages. I don’t have a count of the actual number of messages attempted and successful vs missed. One other thing that is unique about these applications is that in most cases when an application wants to send a message, it opens a socket, sends the message, and closes the socket. That is the behavior in the instances I will point out in these log files. The receiving application is “long running”; starts well before any messages are sent and continues running throughout the entire test run. In the attached source code file, I show the function that applications are calling to close a socket. The function includes waiting for the PURGE event before finishing the steps to close the NORM session. I thought that would allow for the completion of all of the NORM protocol steps, to include an opportunity for NACKs to be received and responded to. I have thought that the TxRobustFactor plays a role in this window of time, meaning that the PURGE event would not occur until after all of the FLUSH commands have been sent, and the duration of the FLUSH commands then provides the window of time for NACKs to be received and responded to. Please correct me on this topic if I misunderstand.

In these log files, there are 35 cases where the receiver NACKs for a missed message. In 31 cases, the missed message is retransmitted and received. In 4 cases, the sender never retransmits the requested message. The instance numbers for these 4 cases are: 49947, 37661, 14389, 53079. When I compared these 4 instances to the other 31, it seemed to me to be related to when the NACK was received in relation to the number of FLUSH commands remaining. So, we ran again with the TxRobustFactor at the default of 20 rather than the value of 5 used in this test run. In new test run, we did not have any cases like these 4. I’m not positive that is “definitive” and not “just chance”. Is it correct that the TxRobustFactor affects this case as I thought?

There are two other kinds of issues represented in these log files, cases where the receiver doesn’t send a NACK at all, though it has missed a message. We have these issues in both test runs, the one with TxRobustFactor = 5 and the one with TxRobustFactor = 20.

In one set of cases (call it case A), the log has messages related to the NACK backoff and a message saying “nothing pending”. In the other set of cases (call it case B), the log doesn’t have any messages about NACKing.

Example instance numbers for case A (21 total cases): 8740, 42282, 21312, 41877, 38384, 35059, 58979, 30328, 3614, 8860, …
Example instance numbers for case B (10 total cases): 29177, 48683, 26194, 21947, 3985, 7705, 17315, 12293, 29120, 8384

As always we very much appreciate your help with the issues we are seeing.

ReceiverLog1539159.txt
SenderLog310722.txt
ProjectSourceCode..txt

[bebopagogo]

Unless your application uses the optional positive acknowledgment mechanism (which can be used for flow control as well as getting an acknowledgment that the receiver(s) got the desired data delivery), the “txRobustFactor” is how you dial in more assurance that receivers will NACK for everything that was sent.   The number of NORM_CMD(FLUSH) messages sent at the end of transmission is driven by that. With txRobustFactor of 5, it is easier to have a burst of loss where the last data message(s) and the 5 flush messages are missing, and the receiver will not NACK for repair if it doesn’t know there are missing messages at the end of transmission.  A higher txRobustFactor reduces the probability of this.    Note if the receiver knows there is a gap in the reception (i.e., it got the last data message sent but missed some prior to that), it will throw an inactivity timeout and NACK even if it misses the sender’s flush messages (the “rxRobustFactor” governs how many times this inactivity cycle is followed).  You can set the “robustFactor” values to -1 if you don’t mind your application being chattier and the sender will send an unbounded series of flush messages at end of transmission or until new data is enqueued. If the transmitter knows the receiver ids (or uses the feature that lets it caches those from NACKs, etc), the ACK mechanism can be used to provide additional assurance and the application can choose how many attempts or for how long of a time it attempts to get acknowledgment from the receiver(s).  For example, the normStreamer example, when the ACK option is used, will query the group an indefinite amount of times. I will also take a look at your log files to see if anything is amiss.

[bebopagogo]

I made the change regarding having the SYNC_CURRENT policy sync to FEC block boundaries. Note that one impact of this is that the receiver does not NACK until it reaches the next FEC block boundary which means the latency of the first message output to your application is output. I.e., if SYNC_CURRENT syncs to the first received NORM_DATA message, that content is immediately delivered to the application, but if the sync is done on a block basis, the application won't see any data until the after NACK and repair transmission of earlier packets in the sync block so there will be some delay before the application gets the content for that first FEC block. Is that the behavior you would like?

[marygilliland]

I have to say I don't really know what the FEC block boundaries are, or how they relate to what is in the debug/trace output, which are the DATA and CMD messages. In response to your question, I would turn it around and ask these questions. When no losses are occuring, will the change you describe change the timing of the application level getting a message (in other words, the time of getting the RX_OBJECT_UPDATED events, which indicate that a message is avalible to be read)? Second, when losses and NACKs are occurring, the NORM API already has to keep messages in order, so the retransmissions delay the application receiving data. From what I've seen, most cases of a NACK add about 30 ms to receiving the message; but some cases are 60 ms and some are 90 ms. How much more delay would your change add?

[bebopagogo]

It would not add delay beyond what you already see (the round-trip time and backoff/holdoff timeouts related to efficient ARQ operation). Basically, the "block size" parameter sets the number of NORM_DATA packets per logical FEC block. For highly efficient multicast operation, packet erasure coding using FEC codes is used for more efficient operation than a typical ARQ protocol. The ARQ NACKing is conducted at FEC block boundaries since that is where the receiver(s) know whether they have enough packets to decode a block successfully. When there is no packet loss, the data packets are delivered to the application as soon as they are received, but when packet loss occurs, the FEC block size and round trip timing of your network connection determines how quickly the NACK-based repair transmissions occur. Larger FEC block sizes are more efficient when there is high packet loss but the larger block size drives that latency of repair a little higher and the CPU time required for FEC encoding/decoding is greater.

By syncing on an FEC block basis, this means your late joining receiver would NACK to recover all the packets for the first block id received and the application would start getting data once that block is received ... I.e., the same amount of latency you see when other packet losses occur

So, it sounds like you prefer recovering the first packets for a late joining receiver and the small amount of initial latency is not an issue. With this update, the SYNC_CURRENT behavior would only attempt to recover packets for the current FEC block while, for SYNC_ALL or SYNC_STREAM, a late-joining receiver will attempt to recover all data the sender has buffered (governed by the set stream buffer size) which could be all the way to the beginning of the stream depending on the sender stream buffer size and how late the receiver joins.

Note the ability to dynamically join a stream in progress is fairly unique to a reliable protocol like NORM so the I've tried to provide a small set of pragmatic policies/behaviors to support different application needs. For lower rate messaging applications, I can see the value of the FEC block sync for SYNC_ALL (which was my original intent but I think I must have changed that while dealing with some very high speed applications where a bunch of NACKing when receivers seemed to be detrimental. However I think that later was determined to be the amount of time memory allocation was taking when receivers detected a new stream instead (aside: the "preallocated sender" option remedies this issue when needed for very high speed and very large buffer memory allocations are needed.).

[marygilliland]

I think what you've described will address the issue we observed without creating other havoc.

Regarding your last paragraph, about the ability to dynamically join a stream in progress being fairly unique to a reliable protocol like NORM... From my reading of the API Guide, we have assumed that we could use NORM without modifiying the general behavior of our applications that are based on traditional multicast concepts. One of those concepts is that applications can join at any time and begin receiving the multicast data; and the application won't receive any data that was sent before it joined, but will recieve what is sent after it joins. This was our reason for choosing the SYNC_CURRENT setting. Is this an unexpected way of using the NORM API? Are we trying to do something the API is not intended for?

[bebopagogo]

FYI - I have pushed updated code that will have a NORM receiver recover the full block of information when joining a stream already in progress. To summarize again, there are 3 sync modes SYNC_CURRENT, SYNC_STREAM, and SYNC_ALL. For SYNC_CURRENT, the receiver will assume sync to a detected sender stream at the current FEC block being transmitted (if it joins during block zero, then it will now recover to the beginning of the stream where the prior behavior you observed as syncing to the first seen packet instead of block). For a stream in progress, both SYNC_CURRENT and SYNC_ALL will cause the receiver to send repair request for any buffered data the sender is holding (the amount of stream history is determined by the sender stream buffer size so the sender can limit the largest amount of retransmission that will occur). With any of these sync modes/policies, a receiver can join a stream in progress. It's just a question of the impact to the group your application allows for late joining receivers. You are in keeping with what the API is intended to support ... it's just a question of your preference for behavior as to which sync mode you use. The change I made for SYNC_CURRENT in response to you query is back to the original intended behavior. I had changed it at some point when I was debugging an issue with late joining receivers to very high speed flows. That changes was because it appeared there was a bit of a NACK/retransmit storm for very high data rate streams when receivers initially joined, but I later pinpointed that to the fact that packets were being dropped while large buffer allocations were being made for the high bandwidth*delay use case. The newer "preallocated sender" option that lets a receiver application preallocate those large buffers before the sender begins transmissions was the real solution to that problem, but I had left the modified sync behavior in place. I think it makes sense to change the behavior as you suggest in this thread for most use cases. It is possible a finer-grained, additional sync mode could be added if it is later determined that different behavior is indeed desirable for some use cases. The only latency impact is the initial data seen by the receiver application when joining a stream in progress since a NACK/retransmission may occur to recover a logical FEC block in progress at that time.

[marygilliland]

Thanks Brian. I will carve out some time to try out this update. When you have time, please look at the log files that I posted to this thread on May 5. I think they are showing different situations than this issue with SYNC_CURRENT. Thanks.