Tvheadend

Try to play with 'Fast input switch' and forced UDP RTP port settings. The best debugging method is to capture the network communication, if the satip server does the right job.

Jaroslav Kysela wrote:

Try to play with 'Fast input switch' and forced UDP RTP port settings.

'Fast input switch' was already activated.
I've assigned an UDP port to each tuner, in increments of ten, tuner #1 50010, tuner #2 50020, and so on.

Now I will leave tvh untouched for a week. No setting adjustment, no restart. After that, I'll give you feedback whether the port customizations have resolved the issues.

Thilo Gebers wrote:

Jaroslav Kysela wrote:

Try to play with 'Fast input switch' and forced UDP RTP port settings.

'Fast input switch' was already activated.

It's the default. Try to turn this off, too.

Jaroslav Kysela wrote:

Thilo Gebers wrote:

Jaroslav Kysela wrote:

Try to play with 'Fast input switch' and forced UDP RTP port settings.

'Fast input switch' was already activated.

It's the default. Try to turn this off, too.

All right ... It is turned off now.

For over a week, Tvheadend runs perfectly with the two changed settings. The two tuners are still found and used by Tvheadend. Many thanks to Jaroslav for his support.
In order to find out which setting was responsible for the problems, I will reactivate "Fast input switch" and observe how this affects tuner #1 and #2.

After a good month, TvHeadend is very stable. All tuners are still available. In the meantime version 4.3-1768 is in use. Even so, there are no problems.
I set the following settings: an UDP port was assigned to each tuner. I deactivated "Fast input switch". In addition, I have disabled the "idle scan" on all tuners.

Now we can set the topic to "solved".

Jaroslav, thanks again for your support!

I'm having the exact same issue, even without "Fast input switch" and a static UDP Port assigned. Tvheadend does in this case not receive any UDP Packets (while wireshark shows that they are there). There's also no "ICMP Port unreachable" until shortly after the teardown (I think this should not happen, we should first wait for the response of the server and then close the port), so I assume the port is indeed open the entire time.

Also I think that the last Tuner Status (SNR and Signal Level) is not cleared, if the tuner doesn't send those information the last one will stay in there. Maybe there is something wrong somewhere with the (de)initialization?

@Jaroslav: Any assumption what might be going on here? I'm more than happy to dive into the debugging but I have no idea what could cause a behaviour like this.

Actually after waiting a little they seem to start working again.....

The same happens here, I think I've solved it by incresing the kernel udp buffer. Although I am still not clear at all.
What I have noticed is that the adapters are hung when many frequencies are closed together, for example closing 9 at the same time. Some of them remains at 0 until tvheadend restart.

Today I noticed that sometimes tvheadend doesnt even do the RTP connection to start the Stream. I will need to do some GDB Debugging but first I need to figure out the points that I want to stop and look at (probably right before the RTP is attempting to connect and right before the UDP Socket is prepared and opened).

I've done a little more investigation now: Usually we should have satip_frontend.c:2081 receiving the UDP Data, for some reason this is not happening though, the code never reaches 2081 when the tuner is in this unusable state. The problem must be somewhere in the lines above....

@Jaroslav: Is this thread started for every new tuning or is it setup once when the input source is setup and then re-used? Any idea what I should look for when trying to find the cause of the issue?

Flole Systems graphviz show connection flow and some dead code

Flole Systems wrote:

I've done a little more investigation now: Usually we should have satip_frontend.c:2081 receiving the UDP Data, for some reason this is not happening though, the code never reaches 2081 when the tuner is in this unusable state. The problem must be somewhere in the lines above....

@Jaroslav: Is this thread started for every new tuning or is it setup once when the input source is setup and then re-used? Any idea what I should look for when trying to find the cause of the issue?

It's reused for the fast switch. You may try to analyze '--trace satip' log and eventually add more traces to see where the code gets stuck.

I've added additional traces and I am seeing:

satip: Falling through play
satip: ev⁰.ptr != rtp, returning!

So we properly execute until satip_frontend.c:2079 (I have added another line after that which indicates if we are ready to receive which doesnt get executed when the issue occures) but then something bad happens on the next run in the loop. I have checked exit_flag aswell as fatal and those are not 0 at that point, so we are not exiting early. Unfortunately for me it now fixed itself again so I have to wait for it to happen again. I suspect this is due to the satip server not responding or not responding properly to one request and something in tvheadend doesnt get cleaned up properly then affecting any other following request (for example a non-closed port which would cause any port open operation on the same port to fail for some time until the system automatically frees the port).

Flole Systems, Have you managed to detect the culprit of this problem?

Since I put the UDP ports as static and disabled Fast input I have not had problems again, but it would be nice if the bug could be fixed.

I'm trying hard to get this fixed before the next big release but unfortunately I need to wait for the issue to occur in order to debug what's going on, so I need to be at my computer, have time and notice that a tuner is not working, you can probably imagine how often that's the case

Perhaps, it may be helpful to attach gdb when this occurs and look for "tvh:satip-front" threads to look, where things break up.

Strange solution without reboot.
Disable/enable or viceversa sat>ip server in webui

Guessing but time to get response is too short.

I've tried gdb, the problem is that tvheadend tries to go through all tuners then giving me thousands of threads in gdb making it super hard to figure out which one is the right one. Also I'm always hitting the timeout when using gdb. I've added debug output to everything that could possibly lockup so I will hopefully be able to see it next time.

The problem has appeared again, I rectify.

Static ports and remove Fast input do not solve it.

I have more information though: Unfortunately I forgot one place in the loop where I wanted to add my debug output, and seems like thats the spot that's triggering it. The line I suspect is

if (nfds < 1) continue;

@Jaroslav: Does that already help you somehow? If I had to guess I'd say that maybe a pipe contains data for the old thread and the new thread reads it and then causes issues, or something similar.

The thread lifetime is similar to the frontend lifetime, thus there should not be a problem with the concurent threads. It appears like RTSP is fine, but RTP/UDP stalls for a reason.

Yes and no, we never reach line 2094 which takes care of the RTSP Status receiving, I do not know where the RTP traffic receiving should happen, I thought thats in that function somewhere. If not I need to add more debugging output there.

Maybe my previous post is unclear: We properly do the RTSP for setting up the channel and the server is sending to the correct port specified, just the status receiving is never done aswell as the RTP receiving (which I thought is somewhere in that function aswell but I haven't found it yet).

Yes, RTP packets should be read in line 2094 (udp_multirecv_read call). Appearently, the tvhpoll_wait() is not working as expected (perhaps UDP/RTP and UDP/RTCP file descriptors are in a wrong state or so).

What variables should I look at at that point? Tvhpoll_wait is supposed to wait for the event that triggers when the first data arrives? I can probably even use gdb now that I found a point where only the non-working tuner is stopping, so let me know what I should look for next time I experience this.

The poll is behind the tvhpoll_wait() ( man 3 poll ). You need to check the socket (file descriptor) state.

You may try to add FIONREAD (SIOCINQ) ioctl for the UDP file decriptors to monitor the state.

So I'll check if rtp->fd is not null (if it is I'll print a big warning) and then just do the ioctl there. For good measure I'll do the same thing for rtcp. I'll add that tomorrow and then wait for the next lockup. If anybody has another idea what I should add please kindly make suggestions.

Also I noticed that the Webinterface shows old satip tuner signal status after stopping, waiting and starting a stream until there is a status message, not sure if that's a client (browser) or server thing though, if the client caches this it's no problem (or at least not related), if the server does send that as current status it could indicate another incomplete cleanup somewhere.

Flole Systems Systems If you provide me with a patch with the necessary TRACES, I could check them when the problem appears for me.

More info:

Oct 27 23:44:31 tvheadend[40289]: satip: No NFDS, Continuing!
Oct 27 23:44:31 tvheadend[40289]: satip: RTCP Bytes available: 0
Oct 27 23:44:31 tvheadend[40289]: satip: RTP Bytes available: 0
Oct 27 23:44:31 tvheadend[40289]: satip: Looping
Oct 27 23:44:31 tvheadend[40289]: satip: (ev[0].ptr == rtcp)
Oct 27 23:44:31 tvheadend[40289]: satip: Looping
Oct 27 23:44:31 tvheadend[40289]: satip: Continuing after change!
Oct 27 23:44:31 tvheadend[40289]: satip: Looping
Oct 27 23:44:32 tvheadend[40289]: satip: No NFDS, Continuing!
Oct 27 23:44:32 tvheadend[40289]: satip: RTCP Bytes available: 80
Oct 27 23:44:32 tvheadend[40289]: satip: RTP Bytes available: 1328
Oct 27 23:44:32 tvheadend[40289]: satip: Looping
Oct 27 23:44:32 tvheadend[40289]: satip: No NFDS, Continuing!
Oct 27 23:44:32 tvheadend[40289]: satip: RTCP Bytes available: 80
Oct 27 23:44:32 tvheadend[40289]: satip: RTP Bytes available: 1328
Oct 27 23:44:32 tvheadend[40289]: satip: Looping
Oct 27 23:44:33 tvheadend[40289]: satip: No NFDS, Continuing!
Oct 27 23:44:33 tvheadend[40289]: satip: RTCP Bytes available: 80
Oct 27 23:44:33 tvheadend[40289]: satip: RTP Bytes available: 1328
Oct 27 23:44:33 tvheadend[40289]: satip: Looping
Oct 27 23:44:33 tvheadend[40289]: satip: No NFDS, Continuing!
Oct 27 23:44:33 tvheadend[40289]: satip: RTCP Bytes available: 80
Oct 27 23:44:33 tvheadend[40289]: satip: RTP Bytes available: 1328
Oct 27 23:44:33 tvheadend[40289]: satip: Looping
Oct 27 23:44:34 tvheadend[40289]: satip: No NFDS, Continuing!
Oct 27 23:44:34 tvheadend[40289]: satip: RTCP Bytes available: 80
Oct 27 23:44:34 tvheadend[40289]: satip: RTP Bytes available: 1328
Oct 27 23:44:34 tvheadend[40289]: satip: Looping
Oct 27 23:44:34 tvheadend[40289]: satip: No NFDS, Continuing!
Oct 27 23:44:34 tvheadend[40289]: satip: RTCP Bytes available: 80
Oct 27 23:44:34 tvheadend[40289]: satip: RTP Bytes available: 1328
Oct 27 23:44:34 tvheadend[40289]: satip: Looping
Oct 27 23:44:35 tvheadend[40289]: subscription: 0019: service instance is bad, reason: No input detected 

"Looping" is at the satip_frontend.c:1914, the "No nfds...." and following 2 lines are from 1962, "ev⁰.ptr == rtcp" is from 2080. So it seems like there is data available at that point but the event is not properly notifying the thread about that?

This happened after switching channels fast (zapping through them).

It seems that there is something wrong with the poll. I will try to prepare tvhpoll_dump() or something. Perhaps, we can add tracing to the poll functions, too.

I added tvhpoll_set_trace() function to tvhpoll.c - commit 4eac68f52a132de8313f2c1fcdcc227df540b2b2 . Perhaps, it may help you to find the issue. Activate those traces only for the problematic frontend.

Just for documentation:

Setting this up (for SAT-IP) is as easy as adding after satip_frontend.c:1603

tvhpoll_set_trace(efd, LS_SATIP, 1);

After zapping through the channels I had a different problem this time: The SAT->IP Server never got the request from tvheadend, which was having some weird issues:

Oct 29 16:16:29 tvheadend[41868]: satip: SAT>IP DVB-C Tuner #1 (x.x.x.x@UDP) - starting XXXXX in XXXXX
Oct 29 16:16:29 tvheadend[41868]: satip: epoll wait: events=1 ptr=(nil)
Oct 29 16:16:29 tvheadend[41868]: satip: SAT>IP DVB-C Tuner #1 (x.x.x.x@UDP) - start
Oct 29 16:16:29 tvheadend[41868]: capmt: TVHeadend: Starting CAPMT server for service "XXXXXX" on adapter 0
Oct 29 16:16:29 tvheadend[41868]: subscription: 0277: "x.x.x.x [ XXXXX | Kodi Media Center ]" subscribing on channel "XXXX", weight: 150, adapter: "SAT>IP DVB-C Tuner #1 (x.x.x.x@UDP)", network: "XXXXX", mux: "XXXXX", provider: "XXXX", service: "XXXXX", profile="htsp", hostname="x.x.x.x", username="XXXXXX", client="Kodi Media Center" 
Oct 29 16:16:29 tvheadend[41868]: satip: SAT>IP DVB-C Tuner - local RTP port 49340 RTCP port 49341
Oct 29 16:16:29 tvheadend[41868]: satip: 00CB: SETUP params - &freq=102&sr=6900&msys=dvbc&mtype=256qam&fec=35&specinv=1&pids=0
Oct 29 16:16:29 tvheadend[41868]: satip: epoll mod: fd=111 events=3 oevents=1 ptr=0x5630ead92f40
Oct 29 16:16:29 tvheadend[41868]: tvhpoll: epoll mod failed [No such file or directory]
Oct 29 16:16:29 tvheadend[41868]: satip: epoll mod: fd=111 events=3 oevents=1 ptr=0x5630ead92f40
Oct 29 16:16:29 tvheadend[41868]: tvhpoll: epoll mod failed [No such file or directory] 

This is not really related to the issue I had before where data was received but also it's not the first time I am seeing this. Should I open a seperate issue for this so we can distinguish between "Tvheadend not receiving UDP traffic" and "Tvheadend not subscribing properly"?

After a restart and doing the same thing, zapping through the channels until I see that tuner 1 is no longer getting data, giving it some "cool down time" (1 to 2 minutes) and then using another client to do the logs, the original issue also appeared:

Oct 29 16:36:43 tvheadend[32125]: mpegts: 146MHz in XXXXXXXX - tuning on SAT>IP DVB-C Tuner #1 (XXXXXXX@UDP)
Oct 29 16:36:43 tvheadend[32125]: satip: SAT>IP DVB-C Tuner #1 (XXXXXXX@UDP) - starting 146MHz in XXXXXXXX
Oct 29 16:36:43 tvheadend[32125]: satip: epoll wait: events=1 ptr=(nil)
Oct 29 16:36:43 tvheadend[32125]: satip: SAT>IP DVB-C Tuner #1 (XXXXXXX@UDP) - start
Oct 29 16:36:43 tvheadend[32125]: capmt: TVHeadend: Starting CAPMT server for service "XXXXXXX" on adapter 0
Oct 29 16:36:43 tvheadend[32125]: satip: SAT>IP DVB-C Tuner - local RTP port 36306 RTCP port 36307
Oct 29 16:36:43 tvheadend[32125]: subscription: 016A: "XXXXXXX [ XXXXXXX | Kodi Media Center ]" subscribing on channel "XXXXXXX", weight: 150, adapter: "SAT>IP DVB-C Tuner #1 (XXXXXXX@UDP)$
Oct 29 16:36:43 tvheadend[32125]: satip: epoll add: fd=96 events=1 ptr=0x563c218af6e0
Oct 29 16:36:43 tvheadend[32125]: satip: epoll add: fd=97 events=1 ptr=0x563c1f831010
Oct 29 16:36:43 tvheadend[32125]: satip: 0069: SETUP params - &freq=146&sr=6900&msys=dvbc&mtype=256qam&fec=35&specinv=1&pids=0
Oct 29 16:36:43 tvheadend[32125]: satip: epoll mod: fd=97 events=3 oevents=1 ptr=0x563c1f831010
Oct 29 16:36:43 tvheadend[32125]: satip: Looping
Oct 29 16:36:43 tvheadend[32125]: satip: epoll wait: events=1 ptr=(nil)
Oct 29 16:36:43 tvheadend[32125]: satip: Reading as we have 1
Oct 29 16:36:43 tvheadend[32125]: satip: Read 1
Oct 29 16:36:43 tvheadend[32125]: satip: Looping
Oct 29 16:36:43 tvheadend[32125]: satip: epoll wait: events=2 ptr=0x563c1f831010
Oct 29 16:36:43 tvheadend[32125]: satip: epoll mod: fd=97 events=1 oevents=3 ptr=0x563c1f831010
Oct 29 16:36:43 tvheadend[32125]: satip: (ev[0].ptr == rtcp)
Oct 29 16:36:43 tvheadend[32125]: satip: Looping
Oct 29 16:36:43 tvheadend[32125]: satip: epoll wait: events=1 ptr=0x563c1f831010
Oct 29 16:36:43 tvheadend[32125]: satip: XXXXXXX #1 - new session 482828139 stream id 1281
Oct 29 16:36:43 tvheadend[32125]: satip: 0069: PLAY params[0] - addpids=104,6640,6641,6642,6644,6646
Oct 29 16:36:43 tvheadend[32125]: satip: PID Changed, continuing!
Oct 29 16:36:43 tvheadend[32125]: satip: Looping
Oct 29 16:36:43 tvheadend[32125]: satip: No NFDS, Continuing!
Oct 29 16:36:43 tvheadend[32125]: satip: RTCP Bytes available: 0
Oct 29 16:36:43 tvheadend[32125]: satip: RTP Bytes available: 0
Oct 29 16:36:43 tvheadend[32125]: satip: Looping
Oct 29 16:36:43 tvheadend[32125]: satip: No NFDS, Continuing!
Oct 29 16:36:43 tvheadend[32125]: satip: RTCP Bytes available: 0
Oct 29 16:36:43 tvheadend[32125]: satip: RTP Bytes available: 0
Oct 29 16:36:43 tvheadend[32125]: satip: Looping
Oct 29 16:36:43 tvheadend[32125]: satip: epoll wait: events=1 ptr=(nil)
Oct 29 16:36:43 tvheadend[32125]: satip: Reading as we have 1
Oct 29 16:36:43 tvheadend[32125]: satip: Read 1
Oct 29 16:36:43 tvheadend[32125]: satip: Looping
Oct 29 16:36:43 tvheadend[32125]: satip: No NFDS, Continuing!
Oct 29 16:36:43 tvheadend[32125]: satip: RTCP Bytes available: 0
Oct 29 16:36:43 tvheadend[32125]: satip: RTP Bytes available: 0
Oct 29 16:36:43 tvheadend[32125]: satip: Looping  
....
Oct 29 16:36:44 tvheadend[32125]: satip: Looping
Oct 29 16:36:44 tvheadend[32125]: satip: epoll wait: events=1 ptr=0x563c1f831010
Oct 29 16:36:44 tvheadend[32125]: satip: 0069: PLAY params[0] - addpids=1,16,17
Oct 29 16:36:44 tvheadend[32125]: satip: PID Changed, continuing!
Oct 29 16:36:44 tvheadend[32125]: satip: Looping
Oct 29 16:36:44 tvheadend[32125]: satip: epoll wait: events=1 ptr=0x563c218af6e0
Oct 29 16:36:44 tvheadend[32125]: satip: Locking DVR Lock
Oct 29 16:36:44 tvheadend[32125]: satip: Locked DVR Lock
Oct 29 16:36:44 tvheadend[32125]: satip: Status string: 'ver=1.2;tuner=1281,240,1,15,146.00,,dvbc,qam256,6900,,,,1;pids='
Oct 29 16:36:44 tvheadend[32125]: satip: (ev[0].ptr == rtcp)
Oct 29 16:36:44 tvheadend[32125]: satip: Looping
Oct 29 16:36:44 tvheadend[32125]: satip: epoll wait: events=1 ptr=0x563c1f831010
Oct 29 16:36:44 tvheadend[32125]: satip: (ev[0].ptr == rtcp)
Oct 29 16:36:44 tvheadend[32125]: satip: Looping
Oct 29 16:36:44 tvheadend[32125]: satip: Continuing after change!
Oct 29 16:36:44 tvheadend[32125]: satip: Looping
Oct 29 16:36:44 tvheadend[32125]: satip: epoll wait: events=1 ptr=0x563c218af6e0
Oct 29 16:36:44 tvheadend[32125]: satip: Locking DVR Lock
Oct 29 16:36:44 tvheadend[32125]: satip: Locked DVR Lock
Oct 29 16:36:44 tvheadend[32125]: satip: Status string: 'ver=1.2;tuner=1281,240,1,15,146.00,,dvbc,qam256,6900,,,,1;pids=0,104,6640,6641,6642,6644,6646,1,16,17'
Oct 29 16:36:44 tvheadend[32125]: satip: (ev[0].ptr == rtcp)
Oct 29 16:36:44 tvheadend[32125]: satip: Looping
Oct 29 16:36:45 tvheadend[32125]: satip: No NFDS, Continuing!
Oct 29 16:36:45 tvheadend[32125]: satip: RTCP Bytes available: 0
Oct 29 16:36:45 tvheadend[32125]: satip: RTP Bytes available: 1328
Oct 29 16:36:45 tvheadend[32125]: satip: Looping
Oct 29 16:36:45 tvheadend[32125]: satip: epoll wait: events=1 ptr=0x563c218af6e0
Oct 29 16:36:45 tvheadend[32125]: satip: Locking DVR Lock
Oct 29 16:36:45 tvheadend[32125]: satip: Locked DVR Lock
Oct 29 16:36:45 tvheadend[32125]: satip: Status string: 'ver=1.2;tuner=1281,240,1,15,146.00,,dvbc,qam256,6900,,,,1;pids=0,104,6640,6641,6642,6644,6646,1,16,17'
Oct 29 16:36:45 tvheadend[32125]: satip: (ev[0].ptr == rtcp)
Oct 29 16:36:45 tvheadend[32125]: satip: Looping
Oct 29 16:36:45 tvheadend[32125]: satip: No NFDS, Continuing!
Oct 29 16:36:45 tvheadend[32125]: satip: RTCP Bytes available: 0
Oct 29 16:36:45 tvheadend[32125]: satip: RTP Bytes available: 1328
Oct 29 16:36:45 tvheadend[32125]: satip: Looping
Oct 29 16:36:46 tvheadend[32125]: satip: epoll wait: events=1 ptr=0x563c218af6e0
Oct 29 16:36:46 tvheadend[32125]: satip: Locking DVR Lock
Oct 29 16:36:46 tvheadend[32125]: satip: Locked DVR Lock
Oct 29 16:36:46 tvheadend[32125]: satip: Status string: 'ver=1.2;tuner=1281,240,1,15,146.00,,dvbc,qam256,6900,,,,1;pids=0,104,6640,6641,6642,6644,6646,1,16,17'
Oct 29 16:36:46 tvheadend[32125]: satip: (ev[0].ptr == rtcp)

Is it possible that the data is available before the eventpoll so it wont trigger when more data is available?

Seems like something is indeed going missing there. Modified Code:

   memset(ev, 0, sizeof(ev));
   nfds = 0;
   if ((rtsp_flags & SATIP_SETUP_TCP) == 0) {
     tvhtrace(LS_SATIP, "Setting up RTP event for %d at %d", rtp->fd, nfds);
     ev[nfds].events = TVHPOLL_IN;
     ev[nfds].fd     = rtp->fd;
     ev[nfds].ptr    = rtp;
     nfds++;
     tvhtrace(LS_SATIP, "Setting up RTCP event for %d at %d", rtcp->fd, nfds);
     ev[nfds].events = TVHPOLL_IN;
     ev[nfds].fd     = rtcp->fd;
     ev[nfds].ptr    = rtcp;
     nfds++;
   } else {
     tvhtrace(LS_SATIP, "Not setting up events as we are doing TCP");
     rtsp->hc_io_size           = 128 * 1024;
     rtsp->hc_rtp_data_received = satip_frontend_rtp_data_received;
   }
   if (i) {
     tvhtrace(LS_SATIP, "Setting up RTSP event for %d at %d", rtsp->hc_fd, nfds);
     ev[nfds].events = TVHPOLL_IN;
     ev[nfds].fd     = rtsp->hc_fd;
     ev[nfds].ptr    = rtsp;
     nfds++;
   }
   tvhtrace(LS_SATIP, "Actually adding our list");
   tvhpoll_add(efd, ev, nfds);
   rtsp->hc_efd = efd;

Logs:

Oct 31 14:08:32 tvheadend[36949]: satip: SAT>IP DVB-C Tuner - local RTP port 59788 RTCP port 59789
Oct 31 14:08:32 tvheadend[36949]: satip: Setting up RTP event for 116 at 0
Oct 31 14:08:32 tvheadend[36949]: satip: Setting up RTCP event for 117 at 1
Oct 31 14:08:32 tvheadend[36949]: satip: Setting up RTSP event for 119 at 2
Oct 31 14:08:32 tvheadend[36949]: satip: Actually adding our list
Oct 31 14:08:32 tvheadend[36949]: satip: epoll add: fd=117 events=1 ptr=0x558184cc60b0
Oct 31 14:08:32 tvheadend[36949]: satip: epoll add: fd=119 events=1 ptr=0x55818394be00
Oct 31 14:08:32 tvheadend[36949]: satip: 0050: SETUP params - XXX
Oct 31 14:08:32 tvheadend[36949]: satip: epoll mod: fd=119 events=3 oevents=1 ptr=0x55818394be00 

Any idea what could be going on here? Would GDB help in this case?

Shouldnt a new thread start for this anyways as I have "Fast Input Switch" disabled and all the old variables should be "forgotten"/reinitialized?

I looked at the stopping part of the tune shown above and there's this:

Oct 31 14:08:37 tvheadend[36949]: subscription: 0090: service instance is bad, reason: No input detected
Oct 31 14:08:37 tvheadend[36949]: satip: SAT>IP DVB-C Tuner #1 (XXXX@UDP) - stopping XXXMHz in XXX
Oct 31 14:08:37 tvheadend[36949]: satip: epoll wait: events=1 ptr=(nil)
Oct 31 14:08:37 tvheadend[36949]: satip: Reading as we have 1
Oct 31 14:08:37 tvheadend[36949]: satip: Read 1 
Oct 31 14:08:37 tvheadend[36949]: satip: SAT>IP DVB-C Tuner #1 (XXXX@UDP) - input thread received mux close
Oct 31 14:08:37 tvheadend[36949]: satip: epoll rem: fd=116 events=1
Oct 31 14:08:37 tvheadend[36949]: tvhpoll: epoll del failed [No such file or directory]
Oct 31 14:08:37 tvheadend[36949]: satip: epoll rem: fd=69 events=1
Oct 31 14:08:37 tvheadend[36949]: satip: SAT>IP DVB-C Tuner #1 (XXXX@UDP) - shutdown for /stream=1529/1052106672  

So fd 116 is not added (which is a problem I guess) and can not be removed because it was never added?

Do you need the epoll rem lines of a working tune on the same tuner? Whats happening now is that when zapping through the channels the tuner stops working at some point (I do not know when exactly that is) and when I stop zapping after about 50 channels its broken. Then I turn on the tracing and try to tune to a channel, tuner 1 fails and tuner 2 succeeds in this case. Where in this process should I look for the lines? I hope you dont need me to find the last working tune somewhere in this process?

I guess the only way this could happen is when tvhpoll.c:187 is true.....

Flole Systems wrote:

Shouldnt a new thread start for this anyways as I have "Fast Input Switch" disabled and all the old variables should be "forgotten"/reinitialized?

I looked at the stopping part of the tune shown above and there's this:
[...]

So fd 116 is not added (which is a problem I guess) and can not be removed because it was never added?

I don't think that 116 was not added. In that case tvhpoll_get_events() will return zero. The question is why we see "epoll del failed [No such file or directory]" . You may try to remove the break in tvhpoll_rem0(), but the question remains - what happened with fd 116? What's the state of this file descriptor when this error occurs? It's closed? ...

Are you sure about that? As you can see in my code above it is added to ev and ev is passed to tvhpoll_add but there is no line indicating that it was actually added to the epoll. That would also explain why there is data and the wait is not noticing that data and why removing it fails (cause its not added so it cant be removed) with said error:

ENOENT op was EPOLL_CTL_MOD or EPOLL_CTL_DEL, and fd is not registered with this epoll instance.

So I think the problem here is that adding it is already failing for some reason.

I thought that we are talking about this scenario:

stream #1:
  poll add ok
  poll rem error

stream #2:
  poll add not visible
  ....

If it's this:

stream:
  poll add not visible
  poll rem error

Then we should determine why the poll add trace is not visible (run) for the RTP file descriptor.

The only explanation for 116 not being added is that inside function "tvhpoll_add0", this condition is true:

    if (oevents == events) continue;

Not sure this "if" makes sense... what does it do?

Can you mod the code (ir use gdb) to print the contents of variables:
events, oevents and fd
?

We are talking about this (done at a speed of about 2 steps per second, so fast zapping basically):

Stream #1 start
Stream #1 stop
Stream #1 start
Stream #1 stop
.....
Stream #1 start
No Data Coming in

For Debugging I do (same speed as above):

Stream #1 start
Stream #1 stop
Stream #1 start
Stream #1 stop
...
Stream #1 start
No Data Coming in
Stream #1 stop
Stream #1 start
No Data Coming in
Stream #1 stop
.....
Wait 10-20s
Stream #1 start
No Data Coming in

The if in that line is there to prevent double-adds if I see that correctly (If someone could confirm this that'd be great). I'm going to add a trace to it there so we can see if something is skipped

The code has 2 modes: kqueue and epoll.
I the default is epoll.
Have you tried to compile using kqueue?

./configure --disable-epoll --enable-kqueue

Kqueue is BSD/MacOS, epoll is Linux. The default should be selected based on what the system supports, Linux is kqueue incompatible and I won't set up a VM (or even switch the OS) for this test.

I also think that the poll layer have the fd registered (thus oevents == events condition is true).

Looking to the code again and it seems that the issue may be the 'goto done' in satip_frontend.c . The done label is bellow the tvhpoll_rem(), but it closes the rtcp/rtp UDP file descriptors. The 's' (start) pipe command may invoke this code path. Because epoll caches the file descriptor event subscription, it seems that the old events are in the cache.

Could you try latest ? (commit 25a50f75a07b656e380b4e9e2d61cbc6c7740e4b ?)

The original issue appears to be fixed now! Thank you so much for your help, its great to have support from someone who knows the code very well, without you it would be very hard to find bugs like this one! I really appreciate the time you spent troubleshooting this.

I will do some more checks later on and see if the other issue where no request is sent appears again but so far I didn't see that since the change you made.

It ended up having duplicate code.

Does the poll remove code really need to be before the "if (exit_flag)" ?
If not, we could simply have 1 poll remove block, after the "done:" label.

I know that the fix is not perfect. I need to review again the done label callers and try to optimize those bits. The satip_frontend_shutdown() should be called without RTP/RTCP file descriptors otherwise the tvhpoll_wait() loop will eat 100% CPU (there might be some data before the SAT>IP server replies to TEARDOWN).