packet_recevier_soapy gets stuck after some time

[daniestevez]

After some time processing many packets (e.g., some minutes of iperf3 TCP transfer), the packet_receiver_soapy flowgraph gets stuck producing lots of invalid header decodes.

The problem seems to be that the Costas loop is at some point called with 65536 input items, which its upstream block (Payload Metadata Insert) never published.

gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>> got syncword_amplitude tag
syncword received for packet 689: amplitude = 0.0618, frequency = 0.0001886 (bin 0), Es/N0 = 23.8 dB, time est = 0.2489
gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>> consumed = 192, published = 192
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 64, outSpan.size() = 64)
gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>>::processBulk(headerSpan.size() = 0, inSpan.size() = 6025, outSpan.size() = 6025), _in_packet = true, _position = 192, _payload_symbols = 6016
gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>> consumed = 0, published = 0
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 128, outSpan.size() = 128)
header data = [5, 220, 0, 85, 194, 168, 138, 174, 173, 107, 89, 62, 59, 216, 80, 248]
gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>>::processBulk(headerSpan.size() = 1, inSpan.size() = 6036, outSpan.size() = 6036), _in_packet = true, _position = 192, _payload_symbols = 6016
header for packet 689: packet_length = 1500, packet_type = USER_DATA
gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>> consumed = 6036, published = 6016
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 6016, outSpan.size() = 6016)
gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>>::processBulk(headerSpan.size() = 0, inSpan.size() = 192, outSpan.size() = 192), _in_packet = false, _position = 6208, _payload_symbols = 6016
gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>> got syncword_amplitude tag
syncword received for packet 690: amplitude = 0.06187, frequency = 0.0006151 (bin 0), Es/N0 = 24 dB, time est = 0.2479
gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>> consumed = 192, published = 192
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 64, outSpan.size() = 64)
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 128, outSpan.size() = 128)
header data = [5, 220, 0, 85, 194, 168, 138, 174, 173, 107, 89, 62, 59, 216, 80, 248]
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 65536, outSpan.size() = 65536)
header data = [171, 237, 208, 24, 238, 18, 189, 48, 209, 186, 84, 135, 13, 235, 11, 198]
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 65536, outSpan.size() = 65536)
header data = [173, 226, 251, 125, 83, 81, 238, 11, 204, 195, 149, 14, 121, 167, 205, 237]
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 128, outSpan.size() = 128)
header data = [202, 82, 205, 110, 213, 79, 174, 58, 115, 47, 164, 78, 146, 89, 183, 90]
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 128, outSpan.size() = 128)
header data = [88, 253, 79, 101, 107, 119, 149, 128, 147, 185, 13, 71, 158, 204, 50, 135]
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 128, outSpan.size() = 128)
header data = [22, 77, 58, 96, 84, 97, 180, 178, 148, 133, 112, 72, 170, 124, 211, 187]

[daniestevez]

I've found that the problem is that at some point the state of the input buffer for CostasLoop becomes invalid and the buffer believes that there are nearly 2**64 items available:

_buffer->_claimStrategy._publishCursor.value() = 0, _readIndexCached = 1009593564
gr::packet_modem::CostasLoop<float, float> input available = 18446744072699958052

[daniestevez]

PublishableOutputRange calling _claimStrategy.publish(140596416, 192)
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596416, _readIndex->value() = 140596416
gr::packet_modem::CostasLoop<float, float> input available = 192
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596416, _readIndex->value() = 140596416
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596416, _readIndex->value() = 140596416
gr::packet_modem::CostasLoop<float, float> input available = 192
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596416, _readIndex->value() = 140596416
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 64, outSpan.size() = 64)
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596416, _readIndex->value() = 140596416
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596416, _readIndex->value() = 140596416
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596480, _readIndex->value() = 140596480
gr::packet_modem::CostasLoop<float, float> input available = 128
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596480, _readIndex->value() = 140596480
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596480, _readIndex->value() = 140596480
gr::packet_modem::CostasLoop<float, float> input available = 128
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596480, _readIndex->value() = 140596480
gr::packet_modem::CostasLoop<float, float>::processBulk(inSpan.size() = 128, outSpan.size() = 128)
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596480, _readIndex->value() = 140596480
_buffer->_claimStrategy._publishCursor.value() = 140596608, _readIndexCached = 140596480, _readIndex->value() = 140596480
header data = [5, 220, 0, 85, 194, 168, 138, 174, 173, 107, 89, 62, 59, 216, 80, 248]
Writer::tryReserve(0), _offset = 140596608
WARNING: PublishableOutputRange(parent) setting _index and _offset to 0
PublishableOutputRange calling _claimStrategy.publish(0, 0)
_buffer->_claimStrategy._publishCursor.value() = 0, _readIndexCached = 140596608, _readIndex->value() = 140596608
gr::packet_modem::CostasLoop<float, float> input available = 18446744073568955008

[daniestevez]

WARNING gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>>::workInternal resampledIn = 0, resampledOut = 0
WARNING Block::prepareStreams() sync_samples == 0
Writer::tryReserve(0), _offset = 506394540
WARNING: PublishableOutputRange(parent) setting _index and _offset to 0
PublishableOutputRange calling _claimStrategy.publish(0, 0)
_buffer->_claimStrategy._publishCursor.value() = 0, _readIndexCached = 506394540, _readIndex->value() = 506394540
gr::packet_modem::CostasLoop<float, float> input available = 18446744073203157076

[daniestevez]

WARNING gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>>::workInternal resampledIn = 0, resampledOut = 0, minSyncIn = 1, nextEosTag = 18446744073709551615, availableToProcess = 0, minSyncOut = 1, availableToPublish = 65536

[daniestevez]

header data = [5, 220, 0, 85, 194, 168, 138, 174, 173, 107, 89, 62, 59, 216, 80, 248]
WARNING gr::packet_modem::PayloadMetadataInsert<std::__1::complex<float>>::workInternal resampledIn = 0, resampledOut = 0, minSyncIn = 1, nextEosTag = 18446744073709551615, availableToProcess = 0, minSyncOut = 1, availableToPublish = 65536, maxSyncIn = 18446744073709551615, maxSyncAvailableIn = 0, hasAsyncIn = true, inputSkipBefore = 0, ensureMinimalDecimation = 18446744073709551615
WARNING Block::prepareStreams() sync_samples == 0
Writer::tryReserve(0), _offset = 88890716
WARNING: PublishableOutputRange(parent) setting _index and _offset to 0
PublishableOutputRange calling _claimStrategy.publish(0, 0)
_buffer->_claimStrategy._publishCursor.value() = 0, _readIndexCached = 88890716, _readIndex->value() = 88890716
gr::packet_modem::CostasLoop<float, float> input available = 18446744073620660900

[daniestevez]

Presumably this has been fixed by https://github.com/fair-acc/gnuradio4/pull/406. Closing.