Project

General

Profile

Bug #2261

sat>ip or htsp - Last subscription takes a very long time to clear, about 10 seconds

Added by Dreamcat 4 about 10 years ago. Updated almost 10 years ago.

Status:
Fixed
Priority:
Normal
Assignee:
John Törnblom
Category:
Streaming
Target version:
-
Start date:
2014-08-29
Due date:
% Done:

0%

Estimated time:
Found in version:
Any recent. Uptadted to 9eea481 of today
Affected Versions:

Description

This problem does not occur when streaming from DVB-T sources. It occur only when channels are coming from the Digibit R1, SAP>IP receiver (any channels).

I can subscribe with any clients, Showtime, XBMC or Plex via plex's tvheadend-ng plugin.
Then I go to Status --> Subscriptions in Web GUI.

If there are 2+ htsp clients subscribed to same stream, then disconnecting / changing channel for the 2nd+ stream will happen instantly.

But if there is only 1 htsp client left connected, then i stop or exit the stream (or change channel). And the Subscription status will still say "Running…" for about 10 second after the stream has stopped. If I try to open a new channel during this time, then the stream will fail --> "Bad". And I have to exit the stream first. Then try again.

I am not sure why tvheadend isn't closing the stream straight away. It is problematic. I have enabled Force Teardown delay and set "Next tune delay" = 14000 ms. However that does not solve the issue.

Opening new stream from scratch is very fast. I takes only about 1 second to start playing. It is only the stopping of stream and freeing up that is taking so long.

I plan to enable trace for satip, httpc, and htsp. But is there any other subsystems you need to see in the trace for this?

History

#1

Updated by Dreamcat 4 about 10 years ago

This is what appears in my log when I close the stream:

2014-08-29 13:31:02.864 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:707) Status string: 'ver=1.0;src=1;tuner=1,80,1,15,10964,h,dvbs,qpsk,off,0.35,22000,56;pids=18,264,2317,2318,2319,2320,3002,3003,0,1,16,17'
2014-08-29 13:31:02.923 [ TRACE]:htsp: (src/htsp_server.c:2101) 192.168.1.18 [ admin | HTS Showtime ] - method unsubscribe
2014-08-29 13:31:02.923 [ INFO]:subscription: "192.168.1.18 [ admin | HTS Showtime ]" unsubscribing from "Channel 5", hostname="192.168.1.18", username="admin", client="HTS Showtime"
2014-08-29 13:31:02.923 [ DEBUG]:satip: (src/input/mpegts/satip/satip_frontend.c:412) SAT>IP DVB-S Tuner #1 (192.168.1.22) - stopping 10964.25H in > 28.2E:Astra
2014-08-29 13:31:02.923 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:420) SAT>IP DVB-S Tuner #1 (192.168.1.22) - waiting for dvr thread
2014-08-29 13:31:02.923 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1082) SAT>IP DVB-S Tuner #1 (192.168.1.22) - input thread received shutdown
2014-08-29 13:31:02.924 [ TRACE]:httpc: (src/httpc.c:608) sending RTSP/1.0 cmd
2014-08-29 13:31:02.924 [ TRACE]:httpc: (src/httpc.c:609) 54 45 41 52 44 4F 57 4E 20 72 74 73 70 3A 2F 2F TEARDOWN rtsp://
2014-08-29 13:31:02.924 [ TRACE]:httpc: (src/httpc.c:609) 31 39 32 2E 31 36 38 2E 31 2E 32 32 2F 73 74 72 192.168.1.22/str
2014-08-29 13:31:02.924 [ TRACE]:httpc: (src/httpc.c:609) 65 61 6D 3D 31 32 37 38 20 52 54 53 50 2F 31 2E eam=1278 RTSP/1.
2014-08-29 13:31:02.924 [ TRACE]:httpc: (src/httpc.c:609) 30 0D 0A 53 65 73 73 69 6F 6E 3A 20 34 30 33 43 0..Session: 403C
2014-08-29 13:31:02.924 [ TRACE]:httpc: (src/httpc.c:609) 30 38 33 41 0D 0A 43 53 65 71 3A 20 35 0D 0A 0D 083A..CSeq: 5...
2014-08-29 13:31:02.924 [ TRACE]:httpc: (src/httpc.c:609) 0A .
2014-08-29 13:31:02.928 [ TRACE]:httpc: (src/httpc.c:908) received RTSP/1.0 answer
2014-08-29 13:31:02.928 [ TRACE]:httpc: (src/httpc.c:909) 52 54 53 50 2F 31 2E 30 20 32 30 30 20 4F 4B 0D RTSP/1.0 200 OK.
2014-08-29 13:31:02.929 [ TRACE]:httpc: (src/httpc.c:909) 0A 43 53 65 71 3A 20 35 0D 0A 53 65 73 73 69 6F .CSeq: 5..Sessio
2014-08-29 13:31:02.929 [ TRACE]:httpc: (src/httpc.c:909) 6E 3A 20 34 30 33 43 30 38 33 41 0D 0A 44 61 74 n: 403C083A..Dat
2014-08-29 13:31:02.929 [ TRACE]:httpc: (src/httpc.c:909) 65 3A 20 46 72 69 2C 20 41 75 67 20 32 39 20 32 e: Fri, Aug 29 2
2014-08-29 13:31:02.929 [ TRACE]:httpc: (src/httpc.c:909) 30 31 34 20 31 32 3A 33 31 3A 30 37 20 47 4D 54 014 12:31:07 GMT
2014-08-29 13:31:02.929 [ TRACE]:httpc: (src/httpc.c:909) 0D 0A 0D 0A ....
2014-08-29 13:31:02.929 [ TRACE]:httpc: (src/httpc.c:950) RTSP/1.0 answer 'RTSP/1.0 200 OK'
2014-08-29 13:31:02.929 [ TRACE]:httpc: (src/httpc.c:608) sending RTSP/1.0 cmd
2014-08-29 13:31:02.929 [ TRACE]:httpc: (src/httpc.c:609) 54 45 41 52 44 4F 57 4E 20 72 74 73 70 3A 2F 2F TEARDOWN rtsp://
2014-08-29 13:31:02.929 [ TRACE]:httpc: (src/httpc.c:609) 31 39 32 2E 31 36 38 2E 31 2E 32 32 2F 73 74 72 192.168.1.22/str
2014-08-29 13:31:02.930 [ TRACE]:httpc: (src/httpc.c:609) 65 61 6D 3D 31 32 37 38 20 52 54 53 50 2F 31 2E eam=1278 RTSP/1.
2014-08-29 13:31:02.930 [ TRACE]:httpc: (src/httpc.c:609) 30 0D 0A 53 65 73 73 69 6F 6E 3A 20 34 30 33 43 0..Session: 403C
2014-08-29 13:31:02.930 [ TRACE]:httpc: (src/httpc.c:609) 30 38 33 41 0D 0A 43 53 65 71 3A 20 36 0D 0A 0D 083A..CSeq: 6...
2014-08-29 13:31:02.930 [ TRACE]:httpc: (src/httpc.c:609) 0A .

2014-08-29 13:31:12.930 [ DEBUG]:satip: (src/input/mpegts/satip/satip_frontend.c:423) SAT>IP DVB-S Tuner #1 (192.168.1.22) - stopped dvr thread

We can see it send a teardown rtsp straight away. Then after 10 seconds nothing in log. Then I guess it must be a pre-programmed timeout of exactly 10 seconds, it say "stopped dvr thread". Exactly then the subscription window clears and can open a new channel again without becoming "Bad" on the new channel.

#2

Updated by Dreamcat 4 about 10 years ago

I can see from this log, and from the code at:

https://github.com/tvheadend/tvheadend/blob/9eea4812da500d2ce8cfeca1232a4aba75fbc038/src/input/mpegts/satip/satip_frontend.c#L1257

That it send the first teardown command, which is accepted in .005 milliseconds, we receive a 200 OK message for it. Then regardless, tvheadend sends a 2nd teardown request again "just to be sure".

At 2nd time, there is no 200 OK response from Digibit R1 (latest firmware 1.16.0.120). It seems tvheadend ignored the first success OK. It leaves the stream open. Was there some other message or acknowledgement it is still left waiting for?

Because when I look on page 46 of SAT>IP protocol specification, the diagram shows nothing after first teardown 200 OK response. It should be end of communication until next setup message is received.

Any help is appreciated.

#3

Updated by Dreamcat 4 about 10 years ago

This is a FreeBSD issue, 50ms timer not working

src/input/mpegts/satip/satip_frontend.c:1280

tvhpoll_wait(efd, ev, 1, 50); --> not working

gets stuck in while loop

tvhpoll.c

#4

Updated by Dreamcat 4 about 10 years ago

My best trace so far:

2014-08-29 16:08:32.794 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:707) Status string: 'ver=1.0;src=1;tuner=1,80,1,15,10964,h,dvbs,qpsk,off,0.35,22000,56;pids=18,264,2317,2318,2319,2320,3002,3003,0,1,16,17'
2014-08-29 16:08:32.987 [ TRACE]:htsp: (src/htsp_server.c:2101) 192.168.1.18 [ admin | HTS Showtime ] - method unsubscribe
2014-08-29 16:08:32.987 [ INFO]:subscription: "192.168.1.18 [ admin | HTS Showtime ]" unsubscribing from "Channel 5", hostname="192.168.1.18", username="admin", client="HTS Showtime"
2014-08-29 16:08:32.987 [ DEBUG]:satip: (src/input/mpegts/satip/satip_frontend.c:412) SAT>IP DVB-S Tuner #1 (192.168.1.22) - stopping 10964.25H in > 28.2E:Astra
2014-08-29 16:08:32.987 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:420) SAT>IP DVB-S Tuner #1 (192.168.1.22) - waiting for dvr thread
2014-08-29 16:08:32.987 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1082) SAT>IP DVB-S Tuner #1 (192.168.1.22) - input thread received shutdown
2014-08-29 16:08:32.987 [ TRACE]:httpc: (src/httpc.c:608) sending RTSP/1.0 cmd
2014-08-29 16:08:32.987 [ TRACE]:httpc: (src/httpc.c:609) 54 45 41 52 44 4F 57 4E 20 72 74 73 70 3A 2F 2F TEARDOWN rtsp://
2014-08-29 16:08:32.988 [ TRACE]:httpc: (src/httpc.c:609) 31 39 32 2E 31 36 38 2E 31 2E 32 32 2F 73 74 72 192.168.1.22/str
2014-08-29 16:08:32.988 [ TRACE]:httpc: (src/httpc.c:609) 65 61 6D 3D 31 32 38 37 20 52 54 53 50 2F 31 2E eam=1287 RTSP/1.
2014-08-29 16:08:32.988 [ TRACE]:httpc: (src/httpc.c:609) 30 0D 0A 53 65 73 73 69 6F 6E 3A 20 35 44 35 37 0..Session: 5D57
2014-08-29 16:08:32.988 [ TRACE]:httpc: (src/httpc.c:609) 44 42 32 35 0D 0A 43 53 65 71 3A 20 35 0D 0A 0D DB25..CSeq: 5...
2014-08-29 16:08:32.988 [ TRACE]:httpc: (src/httpc.c:609) 0A .
2014-08-29 16:08:32.988 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1262) in while(1)
2014-08-29 16:08:32.988 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1263) about to run http_client_run(rtsp)
2014-08-29 16:08:32.988 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1265) step after http_client_run(rtsp)
2014-08-29 16:08:32.988 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1275) r = 6, continuing because r is one of:
2014-08-29 16:08:32.988 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1276) HTTP_CON_RECEIVING = 6, HTTP_CON_SENDING = 4
2014-08-29 16:08:32.988 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1278) about to run tvhpoll_wait
2014-08-29 16:08:32.988 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1280) step after tvhpoll_wait
2014-08-29 16:08:32.988 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1281) nfds = 1
2014-08-29 16:08:32.988 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1289) ev0.events = 2, where:
2014-08-29 16:08:32.988 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1290) TVHPOLL_ERR = 8, TVHPOLL_HUP = 10
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1262) in while(1)
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1263) about to run http_client_run(rtsp)
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1265) step after http_client_run(rtsp)
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1275) r = 6, continuing because r is one of:
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1276) HTTP_CON_RECEIVING = 6, HTTP_CON_SENDING = 4
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1278) about to run tvhpoll_wait
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1280) step after tvhpoll_wait
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1281) nfds = 1
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1289) ev0.events = 2, where:
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1290) TVHPOLL_ERR = 8, TVHPOLL_HUP = 10
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1262) in while(1)
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1263) about to run http_client_run(rtsp)
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1265) step after http_client_run(rtsp)
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1275) r = 6, continuing because r is one of:
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1276) HTTP_CON_RECEIVING = 6, HTTP_CON_SENDING = 4
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1278) about to run tvhpoll_wait
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1280) step after tvhpoll_wait
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1281) nfds = 1
2014-08-29 16:08:32.989 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1289) ev0.events = 1, where:
2014-08-29 16:08:32.990 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1290) TVHPOLL_ERR = 8, TVHPOLL_HUP = 10
2014-08-29 16:08:32.990 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1262) in while(1)
2014-08-29 16:08:32.990 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1263) about to run http_client_run(rtsp)
2014-08-29 16:08:32.990 [ TRACE]:httpc: (src/httpc.c:908) received RTSP/1.0 answer
2014-08-29 16:08:32.990 [ TRACE]:httpc: (src/httpc.c:909) 52 54 53 50 2F 31 2E 30 20 32 30 30 20 4F 4B 0D RTSP/1.0 200 OK.
2014-08-29 16:08:32.990 [ TRACE]:httpc: (src/httpc.c:909) 0A 43 53 65 71 3A 20 35 0D 0A 53 65 73 73 69 6F .CSeq: 5..Sessio
2014-08-29 16:08:32.990 [ TRACE]:httpc: (src/httpc.c:909) 6E 3A 20 35 44 35 37 44 42 32 35 0D 0A 44 61 74 n: 5D57DB25..Dat
2014-08-29 16:08:32.990 [ TRACE]:httpc: (src/httpc.c:909) 65 3A 20 46 72 69 2C 20 41 75 67 20 32 39 20 32 e: Fri, Aug 29 2
2014-08-29 16:08:32.991 [ TRACE]:httpc: (src/httpc.c:909) 30 31 34 20 31 35 3A 30 38 3A 33 37 20 47 4D 54 014 15:08:37 GMT
2014-08-29 16:08:32.991 [ TRACE]:httpc: (src/httpc.c:909) 0D 0A 0D 0A ....
2014-08-29 16:08:32.991 [ TRACE]:httpc: (src/httpc.c:950) RTSP/1.0 answer 'RTSP/1.0 200 OK'
2014-08-29 16:08:32.991 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1265) step after http_client_run(rtsp)
2014-08-29 16:08:32.991 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1268) r = 7 where:
2014-08-29 16:08:32.991 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1269) HTTP_CON_RECEIVING = 6, and HTTP_CON_SENDING = 4
2014-08-29 16:08:32.991 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1270) break;
2014-08-29 16:08:32.991 [ TRACE]:httpc: (src/httpc.c:608) sending RTSP/1.0 cmd
2014-08-29 16:08:32.991 [ TRACE]:httpc: (src/httpc.c:609) 54 45 41 52 44 4F 57 4E 20 72 74 73 70 3A 2F 2F TEARDOWN rtsp://
2014-08-29 16:08:32.991 [ TRACE]:httpc: (src/httpc.c:609) 31 39 32 2E 31 36 38 2E 31 2E 32 32 2F 73 74 72 192.168.1.22/str
2014-08-29 16:08:32.991 [ TRACE]:httpc: (src/httpc.c:609) 65 61 6D 3D 31 32 38 37 20 52 54 53 50 2F 31 2E eam=1287 RTSP/1.
2014-08-29 16:08:32.991 [ TRACE]:httpc: (src/httpc.c:609) 30 0D 0A 53 65 73 73 69 6F 6E 3A 20 35 44 35 37 0..Session: 5D57
2014-08-29 16:08:32.992 [ TRACE]:httpc: (src/httpc.c:609) 44 42 32 35 0D 0A 43 53 65 71 3A 20 36 0D 0A 0D DB25..CSeq: 6...
2014-08-29 16:08:32.992 [ TRACE]:httpc: (src/httpc.c:609) 0A .
2014-08-29 16:08:32.992 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1301) in while(2)
2014-08-29 16:08:32.992 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1302) about to run http_client_run(rtsp)
2014-08-29 16:08:32.992 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1304) step after http_client_run(rtsp)
2014-08-29 16:08:32.992 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1314) r = 6, continuing because r is one of:
2014-08-29 16:08:32.992 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1315) HTTP_CON_RECEIVING = 6, HTTP_CON_SENDING = 4
2014-08-29 16:08:32.992 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1317) about to run tvhpoll_wait
2014-08-29 16:08:32.992 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1319) step after tvhpoll_wait
2014-08-29 16:08:32.992 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1320) nfds = 1
2014-08-29 16:08:32.993 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1335) ev0.events = 2, where:
2014-08-29 16:08:32.993 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1336) TVHPOLL_ERR = 8, TVHPOLL_HUP = 10
2014-08-29 16:08:32.993 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1301) in while(2)
2014-08-29 16:08:32.993 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1302) about to run http_client_run(rtsp)
2014-08-29 16:08:32.993 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1304) step after http_client_run(rtsp)
2014-08-29 16:08:32.993 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1314) r = 6, continuing because r is one of:
2014-08-29 16:08:32.993 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1315) HTTP_CON_RECEIVING = 6, HTTP_CON_SENDING = 4
2014-08-29 16:08:32.993 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1317) about to run tvhpoll_wait
2014-08-29 16:08:32.993 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1319) step after tvhpoll_wait
2014-08-29 16:08:32.993 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1320) nfds = 1
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1335) ev0.events = 1, where:
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1336) TVHPOLL_ERR = 8, TVHPOLL_HUP = 10
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1301) in while(2)
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1302) about to run http_client_run(rtsp)
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1304) step after http_client_run(rtsp)
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1314) r = 6, continuing because r is one of:
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1315) HTTP_CON_RECEIVING = 6, HTTP_CON_SENDING = 4
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1317) about to run tvhpoll_wait
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1319) step after tvhpoll_wait
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1320) nfds = 1
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1335) ev0.events = 2, where:
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1336) TVHPOLL_ERR = 8, TVHPOLL_HUP = 10
2014-08-29 16:08:32.994 [ TRACE]:satip: (src/input/mpegts/satip/satip_frontend.c:1301) in while(2)
2014-08

#6

Updated by Dreamcat 4 about 10 years ago

For the time being we can just disable it since it doesn't work anyway

https://github.com/tvheadend/tvheadend/pull/470

When fix properly kevent, then can re-enable 2nd teardown. Which is a work-around that only affect non-compliant sat>ip hardware. The compliant devices that meed spec to not need to be told twice.

#7

Updated by Dreamcat 4 about 10 years ago

OK. I have looked into this a little more.

  • When I make a small test program, then this timeout method will work reliably and in the way intended, and block for X milliseconds.
  • When I look in the tvheadend code, everything looks the same way as my test program EXCEPT for the contents of the first 2 arguments:

nfds = tvhpoll_wait(efd, ev, 1, 50); /* only small delay here */

There is something BAD about the contents of either the 'efd', or the 'ev' data structures. They are suspicious because have been re-used from previously and their state is not known to me (it is a big complicated function and many things are happening previously I don't know about).

The conclusion is that this bug is occurring due to bad contents of efd data structure. For example the kqueue inside it had previously been de-allocated or some such.

I also wish to say that is very bad API for the purpose of creating a 50ms blocking timer and should not be used that way. You would be better off to define a separate timer function in tvhpoll.h/.c file API method that will always guarantee to create a clean and empty timer each time. For example like in the following way:

tvhpoll_t *new_kqueue = tvhpoll_create(1);
          tvhpoll_event_t tvhpoll_event_data;
          nfds = tvhpoll_wait(new_kqueue, &tvhpoll_event_data, 1, 50);

Where for my test I set a 1 second timer instead of 40 milliseconds. This code replaced the previous existing line and tested today in-situ (where this bug is actually occurring for my satin hardware). And the log shows here just 1 second delay (not the longer 10 seconds thread timeout as before):

2014-09-20 17:12:22.150 [ TRACE]:satip: SAT>IP DVB-S Tuner #1 (192.168.1.22) - input thread received shutdown
2014-09-20 17:12:22.152 [ TRACE]:httpc: received RTSP/1.0 answer
2014-09-20 17:12:22.152 [ TRACE]:httpc: 52 54 53 50 2F 31 2E 30 20 32 30 30 20 4F 4B 0D RTSP/1.0 200 OK.
2014-09-20 17:12:22.152 [ TRACE]:httpc: 0A 43 53 65 71 3A 20 35 0D 0A 44 61 74 65 3A 20 .CSeq: 5..Date:
2014-09-20 17:12:22.152 [ TRACE]:httpc: 53 61 74 2C 20 53 65 70 20 32 30 20 32 30 31 34 Sat, Sep 20 2014
2014-09-20 17:12:22.152 [ TRACE]:httpc: 20 31 36 3A 31 32 3A 35 37 20 47 4D 54 0D 0A 53 16:12:57 GMT..S
2014-09-20 17:12:22.152 [ TRACE]:httpc: 65 73 73 69 6F 6E 3A 20 31 42 30 36 31 37 34 46 ession: 1B06174F
2014-09-20 17:12:22.152 [ TRACE]:httpc: 0D 0A 52 54 50 2D 49 6E 66 6F 3A 20 75 72 6C 3D ..RTP-Info: url=
2014-09-20 17:12:22.152 [ TRACE]:httpc: 72 74 73 70 3A 2F 2F 31 39 32 2E 31 36 38 2E 31 rtsp://192.168.1
2014-09-20 17:12:22.152 [ TRACE]:httpc: 2E 32 32 2F 73 74 72 65 61 6D 3D 33 37 30 30 3B .22/stream=3700;
2014-09-20 17:12:22.152 [ TRACE]:httpc: 73 65 71 3D 32 33 34 33 32 3B 72 74 70 74 69 6D seq=23432;rtptim
2014-09-20 17:12:22.152 [ TRACE]:httpc: 65 3D 32 38 39 33 38 30 39 38 33 38 0D 0A 0D 0A e=2893809838....
2014-09-20 17:12:22.152 [ TRACE]:httpc: RTSP/1.0 answer 'RTSP/1.0 200 OK'
2014-09-20 17:12:22.152 [ TRACE]:httpc: sending RTSP/1.0 cmd
2014-09-20 17:12:22.152 [ TRACE]:httpc: 54 45 41 52 44 4F 57 4E 20 72 74 73 70 3A 2F 2F TEARDOWN rtsp://
2014-09-20 17:12:22.152 [ TRACE]:httpc: 31 39 32 2E 31 36 38 2E 31 2E 32 32 2F 73 74 72 192.168.1.22/str
2014-09-20 17:12:22.152 [ TRACE]:httpc: 65 61 6D 3D 33 37 30 30 20 52 54 53 50 2F 31 2E eam=3700 RTSP/1.
2014-09-20 17:12:22.152 [ TRACE]:httpc: 30 0D 0A 53 65 73 73 69 6F 6E 3A 20 31 42 30 36 0..Session: 1B06
2014-09-20 17:12:22.152 [ TRACE]:httpc: 31 37 34 46 0D 0A 43 53 65 71 3A 20 36 0D 0A 0D 174F..CSeq: 6...
2014-09-20 17:12:22.152 [ TRACE]:httpc: 0A .
2014-09-20 17:12:22.155 [ TRACE]:httpc: received RTSP/1.0 answer
2014-09-20 17:12:22.155 [ TRACE]:httpc: 52 54 53 50 2F 31 2E 30 20 32 30 30 20 4F 4B 0D RTSP/1.0 200 OK.
2014-09-20 17:12:22.155 [ TRACE]:httpc: 0A 43 53 65 71 3A 20 36 0D 0A 53 65 73 73 69 6F .CSeq: 6..Sessio
2014-09-20 17:12:22.155 [ TRACE]:httpc: 6E 3A 20 31 42 30 36 31 37 34 46 0D 0A 44 61 74 n: 1B06174F..Dat
2014-09-20 17:12:22.155 [ TRACE]:httpc: 65 3A 20 53 61 74 2C 20 53 65 70 20 32 30 20 32 e: Sat, Sep 20 2
2014-09-20 17:12:22.155 [ TRACE]:httpc: 30 31 34 20 31 36 3A 31 32 3A 35 37 20 47 4D 54 014 16:12:57 GMT
2014-09-20 17:12:22.155 [ TRACE]:httpc: 0D 0A 0D 0A ....
2014-09-20 17:12:22.155 [ TRACE]:httpc: RTSP/1.0 answer 'RTSP/1.0 200 OK'
2014-09-20 17:12:22.155 [ TRACE]:httpc: sending RTSP/1.0 cmd
2014-09-20 17:12:22.155 [ TRACE]:httpc: 54 45 41 52 44 4F 57 4E 20 72 74 73 70 3A 2F 2F TEARDOWN rtsp://
2014-09-20 17:12:22.155 [ TRACE]:httpc: 31 39 32 2E 31 36 38 2E 31 2E 32 32 2F 73 74 72 192.168.1.22/str
2014-09-20 17:12:22.155 [ TRACE]:httpc: 65 61 6D 3D 33 37 30 30 20 52 54 53 50 2F 31 2E eam=3700 RTSP/1.
2014-09-20 17:12:22.155 [ TRACE]:httpc: 30 0D 0A 53 65 73 73 69 6F 6E 3A 20 31 42 30 36 0..Session: 1B06
2014-09-20 17:12:22.155 [ TRACE]:httpc: 31 37 34 46 0D 0A 43 53 65 71 3A 20 37 0D 0A 0D 174F..CSeq: 7...
2014-09-20 17:12:22.155 [ TRACE]:httpc: 0A .

! here: 1000ms delay

2014-09-20 17:12:23.156 [ DEBUG]:satip: SAT>IP DVB-S Tuner #1 (192.168.1.22) - stopped dvr thread

Not sure why this bug don't appear for linux epoll, but probably because epoll was just not sensitive as it uses different data structures. Or in linux data not was not de-allocated same ways as on freebsd and still remained valid. I don't know.

#8

Updated by Dreamcat 4 about 10 years ago

Of course it is possible to make a quick fix and not change the code around it too much. Just be sure of the contents of those data structures being passed into tvhpoll_wait() are valid / correct.

However I think there is a better lesson to learnt from this. For long-term improvement and avoid future bugs should take 1 of 2 action.

Either:

A)

Improve existing tvhpoll internal API to include some 'clean' blocking timer function. So then when you need a blocking timers (like in that spot), it is guaranteed to always work, and not be subject to the changeable contents of some re-used data structure.

B) Recommended:

Replace all usage of tvhpoll with the cross - platform LIBEVENT library. Which I recommend much more over any other solution. I have seen libevent used in other projects, for example as PHP-FPM and with great success. It does not impact performance anything, yet provides a well defined API. Which can be re-used across different projects and operating systems. And help can be found from other developers who also use lib event.

Of course to start using libevent would mean a new external build dependancy. Unless you choose to import a frozen revision of the libevent code to be within a subdirectory of your project.

#9

Updated by Dreamcat 4 about 10 years ago

Link to new pull request:

https://tvheadend.org/issues/2261

#10

Updated by Jaroslav Kysela almost 10 years ago

  • Status changed from New to Fixed

The second shutdown is not optional (Double RTSP Shutdown option in the device settings). Closing as fixed.

Also available in: Atom PDF