Project

General

Profile

Bug #4353

Minisatip

Added by Ricardo Rocha over 7 years ago. Updated about 7 years ago.

Status:
Fixed
Priority:
Normal
Assignee:
-
Category:
SAT>IP
Target version:
-
Start date:
2017-05-03
Due date:
% Done:

100%

Estimated time:
Found in version:
HTS Tvheadend 4.3-32~g696e17d
Affected Versions:

Description

What's the reason for this errors?

2017-05-03 13:19:24.384 [ ERROR]:satip: SAT>IP DVB-C Tuner #5 (satip01.ddns.net) - RTSP error -90 (Message too long) [9874-0]

log:

https://www.dropbox.com/s/wiiim63y6meeeyl/error90.log?dl=0


Files

diff.txt (2.72 KB) diff.txt catalin toda, 2017-07-21 07:29
debug1.patch (1.95 KB) debug1.patch Jaroslav Kysela, 2017-10-31 12:06

History

#1

Updated by Jaroslav Kysela over 7 years ago

  • Status changed from New to Invalid

The TCP stream from the satip server is broken.

#2

Updated by Ricardo Rocha over 7 years ago

thanks!!!

#3

Updated by Ricardo Rocha over 7 years ago

will report it to catalinii

#4

Updated by catalin toda over 7 years ago

Hi,

is this related to the RTSP message (RTP data) being too long, and the data being corrupted ?

If yes, is it possible to have this as a warning and not close the connection ?

Thanks

#5

Updated by Jaroslav Kysela over 7 years ago

The problem is that the embedded RTSP data are corrupted (the size in the '$' header does not match the received data), so the RTSP session is no longer valid, because tvh (client) cannot parse next RTSP answer.

#6

Updated by Jaroslav Kysela over 7 years ago

The best debugging technique is to capture the whole RTSP TCP stream (using wireshark or tcpdump) and look where the issue is.

#7

Updated by catalin toda over 7 years ago

I have encountered this issue again, added the following patch for better debugging:

diff --git a/src/httpc.c b/src/httpc.c
index 65d6ac7..ca1db05 100644
--- a/src/httpc.c
+++ b/src/httpc.c
@@ -569,6 +569,7 @@ skip:
         http_client_direction(hc, 1);
         return HTTP_CON_SENDING;
       }
+
       return http_client_flush(hc, -errno);
     }
     wcmd->wpos += r;
@@ -696,6 +697,7 @@ http_client_finish( http_client_t *hc )
     res = hc->hc_rtp_data_complete(hc);
     pthread_mutex_lock(&hc->hc_mutex);
     http_client_put(hc);
+    tvhtrace(LS_HTTPC, "here %d", res);
     if (res < 0)
       return http_client_flush(hc, res);
   } else if (hc->hc_data_complete) {
@@ -704,6 +706,7 @@ http_client_finish( http_client_t *hc )
     res = hc->hc_data_complete(hc);
     pthread_mutex_lock(&hc->hc_mutex);
     http_client_put(hc);
+    tvhtrace(LS_HTTPC, "here2 %d", res);
     if (res < 0)
       return http_client_flush(hc, res);
   }
@@ -1004,6 +1007,7 @@ retry:

   if (hc->hc_in_data && !hc->hc_in_rtp_data) {
     res = http_client_data_received(hc, buf, r, 0);
+    tvhtrace(LS_HTTPC, "here3 %d", res);
     if (res < 0)
       return http_client_flush(hc, res);
     if (res > 0) {
@@ -1019,7 +1023,11 @@ retry:

   if (hc->hc_rsize < r + hc->hc_rpos) {
     if (hc->hc_rsize + r > hc->hc_io_size + 20*1024)
+{
+       tvhtrace(LS_HTTPC, "here4 -> %zd %zd %zd ", hc->hc_rsize, r,hc->hc_io_size);
+       tvhlog_hexdump(LS_HTTPC, hc->hc_rbuf, hc->hc_rsize);
       return http_client_flush(hc, -EMSGSIZE);
+}
     hc->hc_rsize += r;
     hc->hc_rbuf = realloc(hc->hc_rbuf, hc->hc_rsize + 1);
   }
@@ -1132,6 +1140,8 @@ rtsp_data:
   hc->hc_in_rtp_data = 0;
   while (hc->hc_rpos > r + 3) {
     hc->hc_csize = 4 + ((hc->hc_rbuf[r+2] << 8) | hc->hc_rbuf[r+3]);
+    int seq = (hc->hc_rbuf[r+6] << 8) | hc->hc_rbuf[r+7];
+    tvhtrace(LS_HTTPC, "here5 %X: hc size %zd seq %d, left %ld", shortid(hc), hc->hc_csize, seq,hc->hc_rpos - r);
     hc->hc_chunked = 0;
     if (r + hc->hc_csize > hc->hc_rpos) {
       memmove(hc->hc_rbuf, hc->hc_rbuf + r, hc->hc_rpos - r);
diff --git a/src/tvhlog.c b/src/tvhlog.c
index f483bbf..88cdcf2 100644
--- a/src/tvhlog.c
+++ b/src/tvhlog.c
@@ -464,11 +464,11 @@ void
 _tvhlog_hexdump(const char *file, int line, int severity,
                 int subsys, const uint8_t *data, ssize_t len )
 {
-  int i, c;
+  int i, c, x = 0;
   char str[1024];

   /* Assume that severify was validated before call */
-
+       tvhlogv(file, line, severity, subsys, "start ", NULL);
   /* Build and log output */
   while (len > 0) {
     c = 0;
@@ -489,6 +489,8 @@ _tvhlog_hexdump(const char *file, int line, int severity,
       c++;
     }
     str[c] = '\0';
+    sprintf(str +strlen(str),"   -> %04X", x);
+    x += 16;
     tvhlogv(file, line, severity, subsys, str, NULL);
     len  -= HEXDUMP_WIDTH;
     data += HEXDUMP_WIDTH;

the stream seems to be fine, but the issue is reproductible almost every time.

the log file is: http://minisatip.org/tmp/log.txt
tcpdump: minisatip.org/tmp/x.pcap
tcpdump.txt: minisatip.org/tmp/tcpdump.txt

Relevant lines:

2017-07-21 05:40:08.976 [  TRACE]:httpc: here4 -> 107973 131072 131072
2017-07-21 05:40:08.977 [  TRACE]:httpc: start
2017-07-21 05:40:08.977 [  TRACE]:httpc: 24 00 1E E4 80 21 38 62 00 65 FA D6 3D 1B 58 BA $....!8b.e..=.X.   -> 0000
2017-07-21 05:40:08.979 [  TRACE]:httpc: CE 45 D1 4F 25 3E 1E 03 24 00 1E E4 80 21 38 62 .E.O%>..$....!8b   -> 1EE0
2017-07-21 05:40:08.980 [  TRACE]:httpc: 24 00 1E E4 80 21 38 5E 00 65 FA D6 3D 1B 58 BA $....!8^.e..=.X.   -> 2360
2017-07-21 05:40:08.982 [  TRACE]:httpc: 24 00 1E E4 80 21 37 F4 00 65 F7 F8 3D 1B 58 BA $....!7..e..=.X.   -> 3DD0
2017-07-21 05:40:08.985 [  TRACE]:httpc: 1B 4E 69 4A A5 40 01 F4 24 00 1E E4 80 21 37 F5 .NiJ.@..$....!7.   -> 5CB0
2017-07-21 05:40:08.989 [  TRACE]:httpc: 24 00 1E E4 80 21 37 F6 00 65 F7 F8 3D 1B 58 BA $....!7..e..=.X.   -> 7BA0
2017-07-21 05:40:08.992 [  TRACE]:httpc: 1A DD 2A D3 C2 F1 23 07 24 00 1E E4 80 21 37 F7 ..*...#.$....!7.   -> 9A80
2017-07-21 05:40:08.995 [  TRACE]:httpc: 24 00 1E E4 80 21 37 F8 00 65 F7 F8 3D 1B 58 BA $....!7..e..=.X.   -> B970
2017-07-21 05:40:08.998 [  TRACE]:httpc: 06 B6 43 A0 D2 4D 0B 08 24 00 04 74 80 21 37 F9 ..C..M..$..t.!7.   -> D850
2017-07-21 05:40:08.999 [  TRACE]:httpc: 24 00 1E E4 80 21 37 FA 00 65 F7 FA 3D 1B 58 BA $....!7..e..=.X.   -> DCD0
2017-07-21 05:40:09.002 [  TRACE]:httpc: 8D 54 B6 DB C1 0F FE 2C 24 00 1E E4 80 21 37 FB .T.....,$....!7.   -> FBB0
2017-07-21 05:40:09.005 [  TRACE]:httpc: 1A 14 DF E7 E0 1B 42 08 D1 47 28 3C 9C 22 82 2F ......B..G(<."./   -> 11A90

In tcpdump:

0025B0DE  c1 0f fe 2c 24 00 1e e4  80 21 37 fb 00 65 f7 fa   ...,$... .!7..e..
0025CFC4  a1 f4 0b 6c d4 38 24 00  1e e4 80 21 37 fc 00 65   ...l.8$. ...!7..e

The beginning of the buffer does not seem right as well: packet 38 62 is repeating twice (pos 0 and 1EE8) and is too new. 3DD0 seems correct but before that is not packet 37 f3.
In the tcpdump seems to be fine (exactly 1FF8 bytes before that packet at 24D412:

    0024D404  a4 9d 80 1a 71 3c ee 04  ae a3 7a 01 3a 24 24 00   ....q<.. ..z.:$$.
    0024D414  1e e4 80 21 37 f3 00 65  f7 f8 3d 1b 58 ba 47 14   ...!7..e ..=.X.G.

Thank you

#8

Updated by catalin toda over 7 years ago

the diff used.

#9

Updated by Ricardo Rocha about 7 years ago

Jaroslav Kysela this keeps happening could you please give a look on what catalin post?

Thanks

#10

Updated by Jaroslav Kysela about 7 years ago

  • Status changed from Invalid to New

Try v4.3-593-g59f98fa3d .

#11

Updated by Mono Polimorph about 7 years ago

Jaroslav Kysela wrote:

Try v4.3-593-g59f98fa3d .

Thank you! This is just the same is I commented at #4573 (http://www.tvheadend.org/issues/4573#note-17)
I'll check it and I post here the results.

Regards!

#12

Updated by Ricardo Rocha about 7 years ago

i didn't have yet much time to test it... just upgraded to last .593 and when epg grab was working i saw this:

2017-10-31 09:52:47.168 mpegts: 322MHz in dvbc - tuning on SAT>IP DVB-C Tuner #1 (satip01.ddns.net:553)
2017-10-31 09:52:47.168 subscription: 0049: "epggrab" subscribing to mux "322MHz", weight: 4, adapter: "SAT>IP DVB-C Tuner #1 (satip01.ddns.net:553)", network: "dvbc", service: "Raw PID Subscription"
2017-10-31 09:53:10.458 satip: SAT>IP DVB-C Tuner #1 (satip01.ddns.net:553) - RTSP error -90 (Message too long) [9874-0]
2017-10-31 10:02:52.168 epggrab: EIT: DVB Grabber - data completion timeout for 322MHz in dvbc
2017-10-31 10:02:52.168 subscription: 0049: "epggrab" unsubscribing
2017-10-31 10:02:53.168 mpegts: 450MHz in dvbc - tuning on SAT>IP DVB-C Tuner #1 (satip01.ddns.net:553)
2017-10-31 10:02:53.168 subscription: 004B: "epggrab" subscribing to mux "450MHz", weight: 4, adapter: "SAT>IP DVB-C Tuner #1 (satip01.ddns.net:553)", network: "dvbc", service: "Raw PID Subscription"
2017-10-31 10:12:58.168 epggrab: EIT: DVB Grabber - data completion timeout for 450MHz in dvbc
2017-10-31 10:12:58.168 subscription: 004B: "epggrab" unsubscribing
2017-10-31 10:12:59.168 mpegts: 354MHz in dvbc - tuning on SAT>IP DVB-C Tuner #1 (satip01.ddns.net:553)
2017-10-31 10:12:59.169 subscription: 004D: "epggrab" subscribing to mux "354MHz", weight: 4, adapter: "SAT>IP DVB-C Tuner #1 (satip01.ddns.net:553)", network: "dvbc", service: "Raw PID Subscription"
2017-10-31 10:15:01.523 satip: SAT>IP DVB-C Tuner #1 (satip01.ddns.net:553) - RTSP error -90 (Message too long) [9874-0]

so maybe the problem still there... will have time to check it better this afternoon.

Jaroslav if you need i can give you access to the system...maybe it's easy for you to debug!

Thanks

#13

Updated by Jaroslav Kysela about 7 years ago

  • File debug1.patch added

Apply this patch and provide '--trace httpc' when you see 'Message too long'.

#14

Updated by Jaroslav Kysela about 7 years ago

  • File deleted (debug1.patch)
#16

Updated by Ricardo Rocha about 7 years ago

Jaroslav:

2017-10-31 16:00:59.978 [  TRACE]:httpc: 0002: rtsp data next header 0 (cut 6032)
2017-10-31 16:00:59.978 [  TRACE]:httpc: 24 00 17 8C 80 21 7D C1 01 25 99 B8 25 E4 5D 32 $....!}..%..%.]2
2017-10-31 16:01:00.009 [  TRACE]:httpc: 0002: new data 11200
2017-10-31 16:01:00.009 [  TRACE]:httpc: 0002: rtsp data 11200
2017-10-31 16:01:00.009 [  TRACE]:httpc: 0002: rtsp data chunk 7912
2017-10-31 16:01:00.009 [  TRACE]:httpc: 0002: rtsp data cont 7912
2017-10-31 16:01:00.009 [  TRACE]:httpc: 0002: finishing
2017-10-31 16:01:00.009 [  TRACE]:httpc: 0002: rtsp data chunk 7912
2017-10-31 16:01:00.009 [  TRACE]:httpc: 0002: rtsp data incomplete 7912
2017-10-31 16:01:00.009 [  TRACE]:httpc: 24 00 1E E4 80 21 7D C3 01 25 99 EC 25 E4 5D 32 $....!}..%..%.]2
2017-10-31 16:01:00.009 [  TRACE]:httpc: 0002: new data 9800
2017-10-31 16:01:00.009 [  TRACE]:httpc: 0002: rtsp data 13088
2017-10-31 16:01:00.009 [  TRACE]:httpc: 0002: rtsp data chunk 7912
2017-10-31 16:01:00.010 [   INFO]:subscription: 0003: "HTTP" unsubscribing from "RTP 1", hostname="ip", client="VLC/2.2.6 LibVLC/2.2.6" 
2017-10-31 16:01:00.014 [  TRACE]:httpc: 0002: rtsp data cont 7912
2017-10-31 16:01:00.014 [  TRACE]:httpc: 0002: finishing
2017-10-31 16:01:00.014 [  TRACE]:httpc: 0002: rtsp data chunk 7912
2017-10-31 16:01:00.014 [  TRACE]:httpc: 0002: rtsp data incomplete 7912
2017-10-31 16:01:00.014 [  TRACE]:httpc: 24 00 1E E4 80 21 7D C4 01 25 99 EC 25 E4 5D 32 $....!}..%..%.]2
2017-10-31 16:01:00.014 [  TRACE]:httpc: 0002: overflow, buf 78361 read 131072 io 131072
2017-10-31 16:01:00.014 [  TRACE]:httpc: 24 00 1E E4 80 21 7D C4 01 25 99 EC 25 E4 5D 32 $....!}..%..%.]2
2017-10-31 16:01:00.014 [  TRACE]:httpc: 0002: client flush -90
2017-10-31 16:01:00.014 [  TRACE]:httpc: 0002: shutdown
2017-10-31 16:01:00.014 [  ERROR]:satip: SAT>IP DVB-C Tuner #1 (host) - RTSP error -90 (Message too long) [9874-0]
2017-10-31 16:01:00.069 [  TRACE]:httpc: 0002: shutdown
2017-10-31 16:01:00.069 [  TRACE]:httpc: 0002: client flush 0
2017-10-31 16:01:00.069 [  TRACE]:httpc: 0002: Closed
2017-10-31 16:01:00.985 [   INFO]:mpegts: 714MHz in dvbc - tuning on SAT>IP DVB-C Tuner #1 (host)
2017-10-31 16:01:00.985 [   INFO]:subscription: 0005: "epggrab" subscribing to mux "714MHz", weight: 4, adapter: "SAT>IP DVB-C Tuner #1 (host)", network: "dvbc", service: "Raw PID Subscripti$
2017-10-31 16:01:01.093 [  TRACE]:httpc: 0003: Connected to host
2017-10-31 16:01:01.093 [  TRACE]:httpc: 0003: sending RTSP/1.0 cmd
2017-10-31 16:01:01.093 [  TRACE]:httpc: 53 45 54 55 50 20 72 74 73 70 3A 2F 2F 73 61 74 SETUP rtsp://host
2017-10-31 16:01:01.093 [  TRACE]:httpc: 69 70 30 31 2E 64 64 6E 73 2E 6E 65 74 3A 35 35 :55
2017-10-31 16:01:01.093 [  TRACE]:httpc: 33 2F 3F 66 65 3D 31 26 66 72 65 71 3D 37 31 34 3/?fe=1&freq=714
2017-10-31 16:01:01.093 [  TRACE]:httpc: 26 73 72 3D 36 38 37 35 26 6D 73 79 73 3D 64 76 &sr=6875&msys=dv
2017-10-31 16:01:01.093 [  TRACE]:httpc: 62 63 26 6D 74 79 70 65 3D 36 34 71 61 6D 20 52 bc&mtype=64qam R
2017-10-31 16:01:01.093 [  TRACE]:httpc: 54 53 50 2F 31 2E 30 0D 0A 54 72 61 6E 73 70 6F TSP/1.0..Transpo
2017-10-31 16:01:01.093 [  TRACE]:httpc: 72 74 3A 20 52 54 50 2F 41 56 50 2F 54 43 50 3B rt: RTP/AVP/TCP;
2017-10-31 16:01:01.093 [  TRACE]:httpc: 69 6E 74 65 72 6C 65 61 76 65 64 3D 30 2D 31 0D interleaved=0-1.
2017-10-31 16:01:01.093 [  TRACE]:httpc: 0A 43 53 65 71 3A 20 31 0D 0A 0D 0A             .CSeq: 1....
2017-10-31 16:01:01.093 [  TRACE]:httpc: 0003: add poll for input and output (2)
2017-10-31 16:01:01.093 [  TRACE]:httpc: 0003: add poll for input and output (3)
2017-10-31 16:01:01.131 [  TRACE]:httpc: 0003: add poll for input (1)
2017-10-31 16:01:01.169 [  TRACE]:httpc: 0003: new data 183
2017-10-31 16:01:01.169 [  TRACE]:httpc: 0003: client flush 0
2017-10-31 16:01:01.169 [  TRACE]:httpc: 0003: RTSP/1.0 answer 'RTSP/1.0 200 OK' (rcseq: 1)
#17

Updated by Jaroslav Kysela about 7 years ago

  • Status changed from New to Fixed
  • % Done changed from 0 to 100

Applied in changeset commit:tvheadend|108a4a8073c2236c119a7265626b7f547988155b.

#18

Updated by Jaroslav Kysela about 7 years ago

Fixed in v4.3-594-g108a4a807 and v4.2.4-6-ge1e1b46c4 .

#19

Updated by Ricardo Rocha about 7 years ago

didn't see more errors... will keep testing and let you know if something happen.

thanks

Also available in: Atom PDF