250ms delay between commands is missing sometimes

[Rayn0r]

In order to figure out way my EXIP418 still reboots at least once a day(after the fixes in the past couple of days), I added a few lines to the code for debugging:

diff --git a/rtsp.c b/rtsp.c
index 63e6dfa..75cf281 100644
--- a/rtsp.c
+++ b/rtsp.c
@@ -12,6 +12,15 @@
 #include "common.h"
 #include "log.h"
 #include "rtsp.h"
+#include <sys/time.h>
+
+long long current_timestamp() {
+    struct timeval te;
+    gettimeofday(&te, NULL); // get current time
+    long long milliseconds = te.tv_sec*1000LL + te.tv_usec/1000; // calculate milliseconds
+    // printf("milliseconds: %lld\n", milliseconds);
+    return milliseconds;
+}

 cSatipRtsp::cSatipRtsp(cSatipTunerIf &tunerP)
 : tunerM(tunerP),
@@ -231,6 +240,7 @@ bool cSatipRtsp::Receive(const char *uriP)
 bool cSatipRtsp::Options(const char *uriP)
 {
   debug1("%s (%s) [device %d]", __PRETTY_FUNCTION__, uriP, tunerM.GetId());
+  error("%lld|OPTIONS|%s|[device %d]", current_timestamp(), uriP, tunerM.GetId());

The "error" line was added to each RTSP function , in order to see when a command was issued.
The cleaned up log then looked like this:

1622310691339|OPTIONS|rtsp://10.6.66.254/|[device 3]
1622310691340|SETUP|rtsp://10.6.66.254/?src=1&freq=11597&pol=v&ro=0.35&msys=dvbs&mtype=qpsk&plts=off&sr=22000&fec=56|[device 3]
1622310691341|DESCRIBE|rtsp://10.6.66.254/STREAM_ID|[device 3]
1622310691587|DESCRIBE|rtsp://10.6.66.254/STREAM_ID|[device 1]
1622310691989|PLAY|rtsp://10.6.66.254/STREAM_ID?addpids=201|[device 2]
1622310692252|PLAY|rtsp://10.6.66.254/STREAM_ID?delpids=201|[device 2]
1622310692342|DESCRIBE|rtsp://10.6.66.254/STREAM_ID|[device 3]
1622310692502|PLAY|rtsp://10.6.66.254/STREAM_ID?addpids=202|[device 2]
1622310692588|DESCRIBE|rtsp://10.6.66.254/STREAM_ID|[device 1]
1622310692844|PLAY|rtsp://10.6.66.254/STREAM_ID?addpids=18|[device 3]
1622310692951|PLAY|rtsp://10.6.66.254/STREAM_ID?delpids=202|[device 2]
1622310693095|PLAY|rtsp://10.6.66.254/STREAM_ID?addpids=0,16,17,20|[device 3]
1622310693096|PLAY|rtsp://10.6.66.254/STREAM_ID?addpids=18,20|[device 1]
1622310693202|PLAY|rtsp://10.6.66.254/STREAM_ID?addpids=662|[device 2]
1622310693347|PLAY|rtsp://10.6.66.254/STREAM_ID?addpids=0,16,17|[device 1]
1622310693543|PLAY|rtsp://10.6.66.254/STREAM_ID?addpids=1090|[device 3]

After I pulled a day worth of log data from VDR, a few lines of Python code showed, that the commands being sent to a particular device sometimes come in without any delay:

waiting: 250.0ms
command: PLAY
uri: rtsp://10.6.66.254/STREAM_ID?delpids=18
device: [device 2]

waiting: 1.0ms
command: PLAY
uri: rtsp://10.6.66.254/STREAM_ID?src=1&freq=11685&pol=v&ro=0.35&msys=dvbs&mtype=qpsk&plts=off&sr=22000&fec=56
device: [device 2]

The standard 250ms delay always seems to be missing right before a new channel is requested.

I also found that after a TEARDOWN, the plugin did not wait before issuing OPTIONS, SETUP & PLAY:

command: TEARDOWN
uri: rtsp://10.6.66.254/STREAM_ID
device: [device 3]

waiting: 1.0ms
command: OPTIONS
uri: rtsp://10.6.66.254/
device: [device 3]

waiting: 1.0ms
command: SETUP
uri: rtsp://10.6.66.254/?src=1&freq=10802&pol=h&ro=0.35&msys=dvbs2&mtype=8psk&sr=22000&fec=34&plts=on
device: [device 3]

waiting: 0.0ms
command: PLAY
uri: rtsp://10.6.66.254/STREAM_ID
device: [device 3]

[rofafor]

Correct. Channel switching is always (almost) instant and resets the pid update cache interval (250ms).