Srt: IPE: ACK node overwritten message (impact unknown)

[ethouris]

There's a message appeared in one of tests:

11:54:57.501306/SRT:RcvQ:worker*E: SRT.c: IPE: ACK node overwritten when acknowledging 1979 (ack extracted: 0)

Impact unknown, although this is qualified as IPE, so it shouldn't happen. This was during tests against 1.1.3 version (Makito) and it might come from the other side. Need to make sure that this kind of problem is never CAUSED by the 1.3 version client.

[ethouris]

Further study states that:

1. The implementation of the ACK window - refactored only formally (just in order to avoid dynamic allocation and too fine-grained delocalization) - is messy, although it's meant to be for relatively simple use. It's hard to say the exact reason that ACK node may be overwritten.
2. A probable reason why this happens is that the ACK window is "too short" and the ACKACK response for ACK message has a journal of an ACK message that has been already wiped out the ACK window. Trouble is, the ACK window has set a size of 1024 elements, and this is about having ACKACK response lacking for the whole window, which is either that the ACKACK response isn't being sent (seems impossible) or lost on track (as larger packets are more probable to be lost, and data packets are not being lost, very hardly possible), or there's some unknown internal implementation problem.
3. The only impact of this event is that the RTT, which is measured as a distance in time between the moment when this ACK message is being sent and when the ACKACK message with the same journal ("ACKNumber") is received, cannot be measured because one of the ingredients for this calculation is missing. RTT is however measured all the time, so losing one opportunity to measure RTT is not a big deal. It would be much worse if such messages appear very often one after another, which means that RTT isn't really being measured, but this isn't the case here.

Research result: minor problem, rather annoying, but it's a developer-uncomfortable situation of an unknown source of problems, even if they are minor.

Recommended: Use some general class of a ring buffer and implement CACKWindow class anew on that base. Important is a possibility to track the running size of the ACK window.

[ethouris]

There should be determined the reason why this node overriding happens. If this isn't anything that influences the overall processing, then the log contents should be changed.

[maxsharabayko]

Message can be seen when netem is applied:

sudo tc qdisc add dev eno1 root netem delay 25ms 10ms loss 4%

SRT default settings with 100 ms latency over a local switch

Note. Delete netem config

sudo tc qdisc del dev eno1 root netem delay 25ms 10ms loss 4%

[ethouris]

When deleting, only the parameters up to root are required.

[stoyanovgeorge]

I am also experiencing the same problem with v.1.4.1. I think this is connected when you have higher jitter.

[ddm1233]

I am also experiencing the same problem with v.1.4.1

client : windows
server : ubuntu 18.04

srt file transfer mode

client call srt_send sync only and server recv sync

[Mutanter]

Well, got these message too.

Pretty constant by using OpenMPTCP link bonding while MLVPN is selected as VPN for ICMP and UDP packet stream.

However, only as soon as the upload bandwidth of one link is completely exhausted by increasing the stream bitrate > eth1 max-upload size, therefore the router has to add a second link (eth2) to the bitstream. This event seems to relate/lead to the message "IPE: ACK node overwritten when acknowledging". From this point, a lot of these messages appear, even though the SRT stream runs smoothly and without visible disturbance. Once the bitrate drops below the maximum upload value of a single uplink gateway the messages disappear.

Let me know if I can provide further information since the test-setup is probably kinda unusual.
Might help you to reproduce the "problem" if it's still a concern.

[Fanfwe]

Hello,
I am experiencing this also.
Based on my tests, this happens when the connection has some jitter, as @stoyanovgeorge also indicated. I have played with this through a network simulator, and the results are pretty clear:
With no jitter, things work fine. I can transport a 1Mbit/s stream, and the actual bandwidth on wire is approx. 1.1/1.2Mbit/s. No messages in the logs either.
Then I introduce a 50ms jitter through the simulator. Right away, I get spammed with a ton of messages in the logs, like the one described above. Another interesting thing is that in the SRT stats, the calculated RTT is still good, but I can see the counter of lost packets increasing, and my bandwidth on-wire jumps to 1.7Mbit/s ! The stream is delivered properly, no lost frames, but at a cost of almost double the bandwidth, where this shouldn't be necessary (the bandwidth available between sender and receiver is way more than 1Mbit/s, and I have configured SRT with a RTT of 3600, which is very, very conservative).

[rationalsa]

I've also seen excessive retransmissions on networks with high jitter / reordering even for packets within their TTL window. This patch took care of it, but it's probably a bit heavy handed. NAKs are still sent through other code paths for packets which are actually lost / late.

[maxsharabayko]

There are two possible reasons for the "ACK node overwritten" error message:

1. incoming ACKACK packet acknowledges some ACK packet that is already missing in the record of the last 1024 ACK packets sent. Full ACK is sent at least every 10 ms, meaning that the last 10 seconds of ACK packets sent are stored. With RTT below this value, it should not be the reason for this message.
2. The estimated RTT value is negative or zero, meaning that there was a shift in clock time, and ACK was sent later than the corresponding ACKACK has been received according to that clock. Should not happen with monotonic/steady clock.
3. Peer error. Sender might have sent some wrong ACKACK packet with a wrong packet sequence number (counter). This value was not found in the records. Similar to no. 1, but a different reason.

int32_t ack = 0;
const int rtt = m_ACKWindow.acknowledge(ctrlpkt.getAckSeqNo(), ack);
if (rtt <= 0)
{
    LOGC(inlog.Error,
            log << CONID() << "IPE: ACK node overwritten when acknowledging " << ctrlpkt.getAckSeqNo()
                << " (ack extracted: " << ack << ")");
    break;
}

TODO

• [x] Split the log message into at least two cases: 1) record not found, and 2) negative RTT estimate.
• [x] Check what happens in the described reproduction step.

[maxsharabayko]

@rationalsa You are disabling periodic NAK reports, which could also be done using the SRTO_NAKREPORT socket option.

To reduce the overhead of retransmissions, please enable a more clever retransmission algorithm using SRTO_RETRANSMITALGO=1.
URI query parameter retransmitalgo=1.

[mbakholdina]

@maxsharabayko
Here is an update on the first test results on the issue. I've performed all the tests using two CentOS7 machines and LanForge network emulator. I haven't been able to reproduce the issue with the latest SRT version (latest master, at least release candidate v1.4.3, commit 449d917aeb3ab10afc338679268b39cd48705062, used srt-xtransmit test application). The following cases were covered:

| Scenario | Link Capacity | RTT | Jitter | Packet Loss | Sending Rate | SRT Settings |
| -------- | ------------- | ------ | ------ | ----------- | ------------ | ----------------------------------------------------------- |
| 1 | 45 Mbps | 100 ms | 1 % | 0 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 2 | 45 Mbps | 100 ms | 10 % | 0 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 3 | 45 Mbps | 100 ms | 20 % | 0 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 4 | 45 Mbps | 100 ms | 50 % | 0 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 5 | 45 Mbps | 100 ms | 50 % | 1 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 6 | 45 Mbps | 100 ms | 50 % | 5 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 7 | 45 Mbps | 100 ms | 50 % | 5 % | 10 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 8 | 45 Mbps | 20 ms | 10 ms | 4 % | 10 Mbps | latency = 80 (4RTT without taking the jitter into account) |

Jitter and packet loss are set up on both ends.

In case 8 which is the reproduction from here, I only see dropped packets. However, it's expected behavior due to high jitter and not enough latency which doesn't take the jitter into account. Should be at least 120.

13:16:58.074516 [D] SOCKET::SRT 0x21A70521 (srt://:4200) Accepted connection 0x21A70520
13:16:58.392392/SRT:TsbPd!W:SRT.br: @564593952:RCV-DROPPED 1 packet(s), packet seqno %1555099858 delayed for 0.084 ms
13:17:18.997238/SRT:TsbPd!W:SRT.br: @564593952:RCV-DROPPED 1 packet(s), packet seqno %1555119440 delayed for 0.094 ms
13:17:54.329206/SRT:TsbPd!W:SRT.br: @564593952:RCV-DROPPED 1 packet(s), packet seqno %1555153018 delayed for 0.093 ms
13:18:25.076541/SRT:TsbPd!W:SRT.br: @564593952:RCV-DROPPED 1 packet(s), packet seqno %1555182239 delayed for 0.059 ms

Commands

_build/bin/srt-xtransmit receive srt://:4200?latency=80 -v
_build/bin/srt-xtransmit generate --sendrate 10Mbps --duration 120 srt://192.168.2.2:4200?latency=80 -v

Next steps:

• [x] The version with extended logs is in progress, see PR #1876.
• [x] Try to reproduce the issue with the help of netem.

[mbakholdina]

@maxsharabayko
Here is an update on the first test results on the issue. I've performed all the tests using two CentOS7 machines and LanForge network emulator. I haven't been able to reproduce the issue with the latest SRT version (latest master, at least release candidate v1.4.3, commit 449d917aeb3ab10afc338679268b39cd48705062). The following cases were covered:

| Scenario | Link Capacity | RTT | Jitter | Packet Loss | Sending Rate | SRT Settings |
| -------- | ------------- | ------ | ------ | ----------- | ------------ | ----------------------------------------------------------- |
| 1 | 45 Mbps | 100 ms | 1 % | 0 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 2 | 45 Mbps | 100 ms | 10 % | 0 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 3 | 45 Mbps | 100 ms | 20 % | 0 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 4 | 45 Mbps | 100 ms | 50 % | 0 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 5 | 45 Mbps | 100 ms | 50 % | 1 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 6 | 45 Mbps | 100 ms | 50 % | 5 % | 1 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 7 | 45 Mbps | 100 ms | 50 % | 5 % | 10 Mbps | latency = 400 (4RTT without taking the jitter into account) |
| 8 | 45 Mbps | 20 ms | 10 ms | 4 % | 10 Mbps | latency = 80 (4RTT without taking the jitter into account) |

In case 8 which is the reproduction from here, I only see dropped packets. However, it's expected behavior due to high jitter and not enough latency which doesn't take the jitter into account. Should be at least 120.

13:16:58.074516 [D] SOCKET::SRT 0x21A70521 (srt://:4200) Accepted connection 0x21A70520
13:16:58.392392/SRT:TsbPd!W:SRT.br: @564593952:RCV-DROPPED 1 packet(s), packet seqno %1555099858 delayed for 0.084 ms
13:17:18.997238/SRT:TsbPd!W:SRT.br: @564593952:RCV-DROPPED 1 packet(s), packet seqno %1555119440 delayed for 0.094 ms
13:17:54.329206/SRT:TsbPd!W:SRT.br: @564593952:RCV-DROPPED 1 packet(s), packet seqno %1555153018 delayed for 0.093 ms
13:18:25.076541/SRT:TsbPd!W:SRT.br: @564593952:RCV-DROPPED 1 packet(s), packet seqno %1555182239 delayed for 0.059 ms

Next steps:

• [ ] The version with extended logs is in progress, see PR #1876.
• [ ] Try to reproduce the issue with the help of netem.

[rationalsa]

@mbakholdina Just adding some jitter with tc qdisc add dev eth0 root netem delay 200ms 40ms seems to be enough to cause this in a 449d917ae srt-live-transmit listener.

[mbakholdina]

Hi @rationalsa,

I confirm the reproduction with the use of netem, srt-xtransmit test application and the SRT version from PR #1876.

I setup tc qdisc add dev eth0 root netem delay 200ms 40ms on the receiver, listener side. The log is the following:

[haivision@big-flop srt-xtransmit]$ _build/bin/srt-xtransmit receive srt://:4200?latency=800 -v
16:35:26.442500 [I] SRC URL: srt://:4200?latency=800
16:35:26.443001 [D] SOCKET::SRT 0x7F93333 (srt://:4200) Listening
16:35:26.443033 [D] SOCKET::SRT 0x7F93333 (srt://:4200) ASYNC Waiting for incoming connection
16:35:35.884545 [D] SOCKET::SRT 0x7F93333 (srt://:4200) Accepted connection 0x7F93332
16:35:36.353145/SRT:RcvQ:w1*E:SRT.in: @133772082:IPE: The record about ACK is not found, RTT estimate at the receiver side can not be calculated (ACK number: 2, last ACK sent: 16, oldest ACK record: not yet available, RTT (EWMA): 115747)
16:35:36.402885/SRT:RcvQ:w1*E:SRT.in: @133772082:IPE: The record about ACK is not found, RTT estimate at the receiver side can not be calculated (ACK number: 4, last ACK sent: 19, oldest ACK record: not yet available, RTT (EWMA): 127244)
16:35:36.554384/SRT:RcvQ:w1*E:SRT.in: @133772082:IPE: The record about ACK is not found, RTT estimate at the receiver side can not be calculated (ACK number: 14, last ACK sent: 30, oldest ACK record: not yet available, RTT (EWMA): 153433)
16:35:36.718613/SRT:RcvQ:w1*E:SRT.in: @133772082:IPE: The record about ACK is not found, RTT estimate at the receiver side can not be calculated (ACK number: 25, last ACK sent: 43, oldest ACK record: not yet available, RTT (EWMA): 164014)

Commands

_build/bin/srt-xtransmit receive srt://:4200?latency=800 -v
_build/bin/srt-xtransmit generate --sendrate 1Mbps --duration 120 srt://192.168.3.2:4200?latency=800 -v

Important
I've just figured out that jitter hasn't been applied in my previous tests with the use of Lanforge. TODO: Figure out the possible reason and replicate some of the tests if required.

[maxsharabayko]

Thanks for the investigation! Now the reason is clear.

The class CACKWindow is responsible for tracking ACK-ACKACK pairs. When ACK is sent, it stores a record with the sending time. When ACKACK is received, it estimates RTT and removes all records older than the current one.

E.g., ACKACK no. 10 arrives on the receiver, ACK records 1-10 are removed.
ACKACK no 9 arrives out of order, there is no record, which results in the IPE message.

TODO

• [ ] Fix ACK window to not remove old records on ACKACK handling. Jitter must affect RTTVar estimate.
• [ ] Consider Drift tracer (blocked by #753)
• [ ] Improve the search for an ACK record knowing that records are stored in order (find by offset).

[ethouris]

Actually I think this node removal was done for a reason - without this you risk that a node will stay there forever if there's no response receiver at all. Moreover, this node is useless at all if a newer ACKACK has come in and did the measurement - the RTT value measured from this "disordered" report would give it falsely exaggerated value. What I think should be fixed here is that the latest updated node up to which the last removal happened should be remembered and when there's coming ACKACK report that is older than this, it should be simply discarded without message. Only unless this was the case should the IPE log be printed.

[ethouris]

I made a short review of the container and procedure used for ACK-window and there are lots of potential improvements that could be done here.

This is implemented as a manually operated cycled array container, in which there are stored values of ACK journal and ACK sequence number. Not sure which is being searched for, but by the call I state it's the journal number, as ACKACK sends only this value (although naming for "sequence" is not exactly unanimous there). This number is being searched linearly, although these numbers are definitely sorted by the fact that they are being increased with every ACK sent. The fact that "all older records than the found one" are being deleted results from that all records that order below the found one are deleted, while they are older because insertion order comes with the time order.

What I think shall be first improved here is that this should now rely on ordering (including the fact that journal number are cyclic numbers that use also the same range as sequence numbers). I wouldn't do a binary search here anyway - this would make sense only for regular numbers, but here are cyclic numbers, which's comparison is more costly, so it wouldn't be too profitable. But a check prematurely whether the incoming sequence number is older than the oldest stored number (and also potentially newer as the newest one, being completely rogue) is perfectly possible, and can simply result in a silent rejection of the case.

The function would also have to change the API a bit so that the state that the node is "already in the past" (for 1/4 of the cycle below the lowest sequence) and "rogue" (for 3/4 of the cycle above the highest sequence) can be distinguished. Maybe it could be also reasonable to keep the last 4 nodes that were deleted "indirectly" so that the out-of-order ACKACKs can be identified.

[maxsharabayko]

@ethouris Good point about potential improvements of the search.
Most of the time no search is expected. If all ACKACK packets arrive, the first record to be checked (the oldest element) would be the search result.
However, if the incoming ACACK does not have a corresponding record, all records (up to 1024) will be iterated to conclude that there is no match. Instead, the range of records in the CACKWindow could be checked first to determine if the search is expected to succeed, not searching otherwise.

[ethouris]

1888 submitted for fixing the problem

[maxsharabayko]

Status Update

SRT v1.4.3 will preserver the current behavior of ignoring out-of-order ACKACK packets. To be improved in further versions.

Meanwhile ,logs have been changed in PR #1876.
Now, the expected log message in case of reordering is the following warning:

... W:SRT.in: ... ACKACK out of order, skipping RTT calculation (ACK number: ###, last ACK sent: ###, RTT (EWMA): ###

Error log will be shown if:

• Incoming ACKACK is for an ACK sent more than 10s ago.
  IPE: ACK record not found, can't estimate RTT ...
• Negative RTT estimation (time shift?)
  IPE: invalid RTT estimate ###, possible time shift. Clock: <clock_type>

Please feel free to check the behavior with the latest master and provide your feedback.