ristsender reference software outputs a suspicious log statement when it first receives data
rist_clean_sender_enqueue
(invoked in the sender thread, https://code.videolan.org/rist/librist/-/blob/master/src/rist-common.c#L2491) logs this message Moving delete index to 1
when the ristsender reference software first receives data. The comment above the log statement states This should never happen!
, which is interesting.
I haven't had time to dig into the functionality of the two sender queue indices to understand how they could assume the values they do to cause the log statement to be invoked.
Steps to reproduce:
- Compile project
- Run ristsender:
ristsender -o rist://127.0.0.1:4754 -i udp://@127.0.0.1:8000 -v 999
- Run ffmpeg:
ffmpeg -f lavfi -re -i testsrc -f mpegts -pkt_size '188*7' udp://127.0.0.1:8000
Output:
1596047165.170782|0.0|[INFO] Starting ristsender version: 3.0.0.2
1596047165.170864|0.0|[INFO] Starting in Main Profile Mode
1596047165.170882|0.0|[INFO] RIST Sender Library 9571621
1596047165.170971|0.4496257024|[INFO] Starting master sender loop at 5 ms max jitter
1596047165.170973|0.0|[INFO] URL parsed successfully: Host 127.0.0.1, Port 8000
1596047165.171062|0.0|[INFO] Input socket is open and bound 127.0.0.1:8000
1596047165.171077|0.0|[INFO] Link configured with maxrate=100000 bufmin=1000 bufmax=1000 reorder=25 rttmin=50 rttmax=500 congestion_control=1 min_retries=6 max_retries=20
1596047165.171081|0.4496257024|[INFO] Encryption is disabled for this peer
1596047165.171095|0.4496257024|[INFO] URL parsed successfully: Host 127.0.0.1, Port 4754
1596047165.171105|0.4496257024|[INFO] Starting in URL connect mode (4)
1596047165.171118|0.4496257024|[INFO] Configured the starting socket receive buffer size to 1048576 Bytes.
1596047165.171122|0.4496257024|[INFO] Configured the starting socket send buffer size to 9216 Bytes.
1596047165.171144|0.4496257024|[INFO] Peer cname is 784f436c128d.ant.amazon.com
1596047165.171146|0.4496257024|[INFO] Setting max nacks per cycle to 44
1596047165.171154|0.4496257024|[INFO] Setting buffer size to 2000ms
1596047165.171157|0.4496257024|[INFO] Advertising flow_id 3097000916 and peer_id 1, 32768/1969
1596047165.171173|0.4496257024|[INFO] Initialized Sender Peer, connecting to receiver ...
1596047165.171180|0.4496257024|[INFO] Active Peer Information, IP:Port => 127.0.0.1:4754 (0), id: 1, ports: 32768->1969
1596047165.171182|0.4496257024|[INFO] Enabling keepalive for peer 1
1596047165.171271|0.4496257024|[INFO] Successfully Authenticated peer 1
1596047165.176807|0.0|[INFO] {"sender-stats":{"peer":{"id":1,"cname":"","stats":{"quality":100,"sent":4,"received":0,"retransmitted":0,"bandwidth":0,"retry_bandwidth":0,"bloat_skipped":0,"retransmit_skipped":0,"rtt":0,"avg_rtt":0,"retry_buffer_size":1,"cooldown_time":0}}}}
...
1596047189.201477|0.4496257024|[ERROR] Moving delete index to 1
1596047190.174165|0.0|[INFO] {"sender-stats":{"peer":{"id":1,"cname":"","stats":{"quality":100,"sent":63,"received":0,"retransmitted":0,"bandwidth":367824,"retry_bandwidth":0,"bloat_skipped":0,"retransmit_skipped":0,"rtt":0,"avg_rtt":0,"retry_buffer_size":1,"cooldown_time":0}}}}
1596047191.176191|0.0|[INFO] {"sender-stats":{"peer":{"id":1,"cname":"","stats":{"quality":100,"sent":41,"received":0,"retransmitted":0,"bandwidth":400460,"retry_bandwidth":0,"bloat_skipped":0,"retransmit_skipped":0,"rtt":0,"avg_rtt":0,"retry_buffer_size":1,"cooldown_time":0}}}}