Bug #4353
closed
Minisatip
Added by Ricardo Rocha almost 8 years ago. Updated over 7 years ago.
100%
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:
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 |
Updated by Jaroslav Kysela almost 8 years ago
- Status changed from New to Invalid
The TCP stream from the satip server is broken.
Updated by catalin toda almost 8 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
Updated by Jaroslav Kysela almost 8 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.
Updated by Jaroslav Kysela almost 8 years ago
The best debugging technique is to capture the whole RTSP TCP stream (using wireshark or tcpdump) and look where the issue is.
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
Updated by catalin toda over 7 years ago
the diff used.
Updated by Ricardo Rocha over 7 years ago
Jaroslav Kysela this keeps happening could you please give a look on what catalin post?
Thanks
Updated by Jaroslav Kysela over 7 years ago
- Status changed from Invalid to New
Try v4.3-593-g59f98fa3d .
Updated by Mono Polimorph over 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!
Updated by Ricardo Rocha over 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
Updated by Jaroslav Kysela over 7 years ago
- File debug1.patch added
Apply this patch and provide '--trace httpc' when you see 'Message too long'.
Updated by Jaroslav Kysela over 7 years ago
- File debug1.patch debug1.patch added
Updated by Ricardo Rocha over 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)
Updated by Jaroslav Kysela over 7 years ago
- Status changed from New to Fixed
- % Done changed from 0 to 100
Applied in changeset commit:tvheadend|108a4a8073c2236c119a7265626b7f547988155b.
Updated by Jaroslav Kysela over 7 years ago
Fixed in v4.3-594-g108a4a807 and v4.2.4-6-ge1e1b46c4 .
Updated by Ricardo Rocha over 7 years ago
didn't see more errors... will keep testing and let you know if something happen.
thanks