Context Navigation

← Previous Ticket
Next Ticket →

Opened 4 years ago

Last modified 2 months ago

#13121 assigned Patch - Feature

Sat>IP client support

Reported by:	cg@…	Owned by:	Klaas de Waal
Priority:	minor	Milestone:	32.0
Component:	MythTV - Recording	Version:	Master Head
Severity:	low	Keywords:
Cc:		Ticket locked:	no

Description

The changes in the branch at https://github.com/cguedel/mythtv/tree/devel/satip add Sat>IP support to the backend. This allows the backend to use Sat>IP compliant networked tuners to record DVB-C/DVB-S/DVB-T programs.

This works relatively stable for me, however I can only test DVB-C on one network. Also, the channel scanner seems to be broken for this network, so I can't really test that.

EIT scanning is also working.

Support for DVB-S is certainly lacking, as the Diseqc configuration is missing altogether.

Also, this only implements the "Unicast Only Profile" as per the Sat>IP spec found at http://www.satip.info/sites/satip/files/resource/satip_specification_version_1_2_2.pdf. Multicast is not supported.

Attachments (10)

gdb.txt (52.4 KB) - added by Mike Bibbings 12 months ago.: gdb.txt backtrace seg fault
mythbackend.20200719123309.24920.log (254.8 KB) - added by Mike Bibbings 12 months ago.: mythbackend log
20200726_satip_teardown.patch (572 bytes) - added by Mike Bibbings 12 months ago.: Teardown patch
gdb.2.txt (43.5 KB) - added by Mike Bibbings 12 months ago.: backtrace chanscan seg fault
mythtv-setup.20200730131428.19054.log.zip (76.2 KB) - added by Mike Bibbings 12 months ago.: mythtv-setup log chanscan seg fault
mythtv-setup.20200809123425.79080.log.zip (973.2 KB) - added by Mike Bibbings 12 months ago.: mythtv-setup log tbs6280
gdb-tbs6280.txt (71.1 KB) - added by Mike Bibbings 12 months ago.: gdb backtrace tbs6280
DroppedPacketLog02-12-20.zip (20.9 KB) - added by jksj461 8 months ago.
ShortRecordings.txt (191.7 KB) - added by jksj461 5 months ago.
debug.txt (832.2 KB) - added by jksj461 5 months ago.: Failed Recording noting short timeout

Change History (76)

comment:1 Changed 4 years ago by Peter Bennett

Component:	MythTV - General → MythTV - Recording
Owner:	set to JYA
Type:	Bug Report - General → Patch - Feature

comment:2 Changed 14 months ago by Klaas de Waal

Owner:	changed from JYA to Klaas de Waal
Status:	new → assigned

comment:3 Changed 13 months ago by Klaas de Waal

Milestone:	needs_triage → 32.0
Severity:	medium → low

Thanks for supplying the patch; it is now in v32/master.

The patch has been updated for today's master and there have been some issues fixed.

Testing has been done with minisatip connnected to a DVB-S2 card in the same machine as the mythbackend and with a Telestar Digibit R1 box.

Satellite LNB selection via DiSeqC is defined in the Sat>IP protocol but is not yet implemented.

It is possible to use the same Video Source for a /dev/dvb tuner and for a Sat>IP tuner when they are connected to the same source.

The Sat>IP support is still a new and relatively untested feature; if anybody finds problems when testing this please add comments to this ticket.

comment:4 Changed 13 months ago by Mike Bibbings

build from source on Xubuntu 18.04 fails:

make[2]: Entering directory '/srv/mike/build/mythtv/mythtv/libs/libmythtv'
ccache g++ -c -pipe -D_FILE_OFFSET_BITS=64 -DPIC -std=c++17 -faligned-new -DNDEBUG -fomit-frame-pointer -fPIC -DQT_DISABLE_DEPRECATED_BEFORE=0x050700 -msse -pthread -g -Wall -Wextra -Wpointer-arith -fvisibility-inlines-hidden -Wdouble-promotion -Wduplicated-cond -Wlogical-op -Wmissing-declarations -Wnull-dereference -Woverloaded-virtual -Wshadow -funit-at-a-time -Wzero-as-null-pointer-constant -Wsuggest-override -I/usr/include/freetype2 -I/usr/include/libpng16 -isystem ../../external/libmythdvdnav/dvdnav -isystem ../../external/libmythdvdnav/dvdread -fvisibility=hidden -D_REENTRANT -fPIC -DMMX -Dusing_libcec -D_GNU_SOURCE -DUSING_LIBCRYPTO -DUSING_LIBASS -DUSING_V4L2PRIME -DUSING_VDPAU -DUSING_VAAPI -DUSING_NVDEC -DFFTW3_SUPPORT -DUSING_X11 -DUSING_OPENGL -DUSING_EGL -DUSING_AIRPLAY -DUSING_MHEG -DUSING_FRONTEND -DUSING_ALSA -DUSING_OSS -DUSING_V4L2 -DUSING_LINUX_FIREWIRE -DUSING_FIREWIRE -DUSING_IPTV -DUSING_HDHOMERUN -DHDHOMERUN_HEADERFILE=\"libhdhomerun/hdhomerun.h\" -DHDHOMERUN_V2 -DUSING_SATIP -DUSING_VBOX -DUSING_CETON -DUSING_IVTV -DUSING_HDPVR -DUSING_DVB -DUSING_BACKEND -DMTV_API -DQT_WIDGETS_LIB -DQT_GUI_LIB -DQT_NETWORK_LIB -DQT_XML_LIB -DQT_SQL_LIB -DQT_CORE_LIB -I. -isystem /usr/include/libxml2 -isystem /usr/include/X11 -I.. -I../.. -I../.. -I../../external/FFmpeg -I. -I../libmyth -I../libmyth/audio -I../libmythbase -Impeg -Ichannelscan -Ivisualisations -Imheg -Idecoders -Iopengl -Iio -Icaptions -Irecorders -Irecorders/dvbdev -Irecorders/rtp -Irecorders/vbitext -Irecorders/HLS -I../libmythlivemedia/BasicUsageEnvironment/include -I../libmythlivemedia/BasicUsageEnvironment -I../libmythlivemedia/groupsock/include -I../libmythlivemedia/groupsock -I../libmythlivemedia/liveMedia/include -I../libmythlivemedia/liveMedia -I../libmythlivemedia/UsageEnvironment/include -I../libmythlivemedia/UsageEnvironment -I../libmythbase -I../libmythui -I../libmythupnp -I../libmythservicecontracts -I../../external/libmythdvdnav/dvdnav -I../../external/libmythdvdnav/dvdread -I../../external/nv-codec-headers/include -isystem /usr/include/x86_64-linux-gnu/qt5 -isystem /usr/include/x86_64-linux-gnu/qt5/QtWidgets -isystem /usr/include/x86_64-linux-gnu/qt5/QtGui -isystem /usr/include/x86_64-linux-gnu/qt5/QtNetwork -isystem /usr/include/x86_64-linux-gnu/qt5/QtXml -isystem /usr/include/x86_64-linux-gnu/qt5/QtSql -isystem /usr/include/x86_64-linux-gnu/qt5/QtCore -Imoc -isystem /usr/include/libdrm -I/usr/lib/x86_64-linux-gnu/qt5/mkspecs/linux-g++ -o obj/satipstreamhandler.o recorders/satipstreamhandler.cpp
recorders/satipstreamhandler.cpp: In member function ‘virtual void SatIPStreamHandler::run()’:
recorders/satipstreamhandler.cpp:184:14: error: ‘std::this_thread’ has not been declared
         std::this_thread::sleep_for(std::chrono::milliseconds(40));
              ^~~~~~~~~~~
Makefile:18961: recipe for target 'obj/satipstreamhandler.o' failed
make[2]: *** [obj/satipstreamhandler.o] Error 1
make[2]: Leaving directory '/srv/mike/build/mythtv/mythtv/libs/libmythtv'
Makefile:265: recipe for target 'sub-libmythtv-make_first' failed
make[1]: *** [sub-libmythtv-make_first] Error 2
make[1]: Leaving directory '/srv/mike/build/mythtv/mythtv/libs'
Makefile:66: recipe for target 'libs' failed
make: *** [libs] Error 2

buildbot for master ubuntu 18.04 is also showing failure https://code.mythtv.org/buildbot/#/builders/22/builds/713

build from source on Xubuntu 20.04 is ok.

Mike

comment:5 Changed 13 months ago by Klaas de Waal <kdewaal@…>

In c56ac71e6a/mythtv:

Fix compiler warning

Fixed compiler warning about use of NULL instead of nullptr.

Refs #13121

comment:6 Changed 12 months ago by Klaas de Waal

There is an issue with Multirec and EIT on the SatIP tuner. This can be avoided by disabling Multirec. To do that set the "Max Recordings" to 1 and uncheck the "Schedule as Group" in the Input Connections dialog of mythtv-setup.

comment:7 Changed 12 months ago by Mike Bibbings

Klaas,

In mythtv-setup Capture Card for Sat>IP I think an "Enable/Disable? EIT" checkbox is required. I ran a quick test with 4 x DVB/S2 tuners setup in minisatip and EIT processing was continuously running on all 4 tuners.

Whilst on the subject of eit, does "SATIP" need to be added in https://github.com/MythTV/mythtv/blob/master/mythtv/libs/libmythtv/tv_rec.cpp

void TVRec::CloseChannel(void)
{
    if (m_channel &&
        ((m_genOpt.m_inputType == "DVB" && m_dvbOpt.m_dvbOnDemand) ||
         m_genOpt.m_inputType == "FREEBOX" ||
         m_genOpt.m_inputType == "VBOX" ||
         m_genOpt.m_inputType == "HDHOMERUN" ||
         CardUtil::IsV4L(m_genOpt.m_inputType)))
    {
        m_channel->Close();
    }
}

Mike

comment:8 Changed 12 months ago by Mike Bibbings

Klaas,

Just tried DVB-T/T2 UK Freeview and it basically worked, although the "SETUP" messages are out of specification (minisatip does not seem to care), a couple of examples:

Jul 16 13:34:13 2004-satip mythbackend: mythbackend[6844]: D CoreContext recorders/satiprtsp.cpp:233 (sendMessage) SatIPRTSP[2]: sendMessage write: SETUP rtsp://192.168.0.221:554/?freq=498.00&bw=8&msys=dvbt&tmode=auto&mtype=unknownqam&gi=132&fec=auto RTSP/1.0

Jul 16 13:38:08 2004-satip mythbackend: mythbackend[6844]: D TVRecEvent recorders/satiprtsp.cpp:233 (sendMessage) SatIPRTSP[2]: sendMessage write: SETUP rtsp://192.168.0.221:554/?freq=474.00&bw=8&msys=dvbt2&tmode=auto&mtype=unknownqam&gi=132&fec=auto RTSP/1.0

Here are contents of dtv_multiplex table after channel scan:

------+---------+---------------+-----------+--------------+---------+---------+------------+----------------+---------------------+-------------------+
| mplexid | sourceid | transportid | networkid | frequency | inversion | symbolrate | fec  | polarity | modulation | bandwidth | lp_code_rate | transmission_mode | guard_interval | visible | constellation | hierarchy | hp_code_rate | mod_sys | rolloff | sistandard | serviceversion | updatetimestamp     | default_authority |
+---------+----------+-------------+-----------+-----------+-----------+------------+------+----------+------------+-----------+--------------+-------------------+----------------+---------+---------------+-----------+--------------+---------+---------+------------+----------------+---------------------+-------------------+
|       1 |        1 |       16515 |      9018 | 474000000 | 0         |          0 | auto | v        | auto       | 8         | auto         | a                 | 1/32           |       0 | auto          | n         | auto         | DVB-T2  | 0.35    | dvb        |             33 | 2020-07-16 12:40:44 |                   |
|       2 |        1 |        8194 |      9018 | 498000000 | 0         |          0 | auto | v        | auto       | 8         | auto         | a                 | 1/32           |       0 | auto          | n         | auto         | DVB-T   | 0.35    | dvb        |             33 | 2020-07-16 12:40:44 |                   |
|       3 |        1 |        4173 |      9018 | 522000000 | 0         |          0 | auto | v        | auto       | 8         | auto         | a                 | 1/32           |       0 | auto          | n         | auto         | DVB-T   | 0.35    | dvb        |             33 | 2020-07-16 12:40:44 |                   |
|       4 |        1 |       12294 |      9018 | 570000000 | 0         |          0 | auto | v        | auto       | 8         | auto         | a                 | 1/32           |       0 | auto          | n         | auto         | DVB-T   | 0.35    | dvb        |             33 | 2020-07-16 12:40:44 |                   |
|       5 |        1 |       20544 |      9018 | 594000000 | 0         |          0 | auto | v        | auto       | 8         | auto         | a                 | 1/32           |       0 | auto          | n         | auto         | DVB-T   | 0.35    | dvb        |             33 | 2020-07-16 12:40:44 |                   |
|       6 |        1 |       24640 |      9018 | 690000000 | 0         |          0 | auto | v        | auto       | 8         | auto         | a                 | 1/32           |       0 | auto          | n         | auto         | DVB-T   | 0.35    | dvb        |             33 | 2020-07-16 12:40:44 |                   |
|       7 |        1 |       40960 |      9018 | 746000000 | 0         |          0 | auto | v        | auto       | 8         | auto         | a                 | 1/32           |       0 | auto          | n         | auto         | DVB-T2  | 0.35    | dvb        |             33 | 2020-07-16 12:40:44 |                   |
+---------+----------+-------------+-----------+-----------+-----------+------------+------+----------+------------+-----------+--------------+-------------------+----------------+---------+---------------+-----------+--------------+---------+---------+------------+----------------+---------------------+-------------------+
7 rows in set (0.00 sec)

Test Configuration:

MythTV Version : v32.0~master.202007151913.b76dbf4~ubuntu20.04.1 combined FE/Backend

UK Freeview from SandyHeath? transmitter

tuner is TBS 6280 Dual DVB-T/T2 PCI-e using TBS drivers with kernel Linux 2004-satip 5.4.0-40-generic #44-Ubuntu SMP Tue Jun 23 00:01:04 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux under Xubuntu 20.04

Minisatip Version: 1.0.3-e8bb03b running on same hardware as mythbackend

Mike

comment:9 Changed 12 months ago by Klaas de Waal <kdewaal@…>

In 8cf47d3c2c/mythtv:

Sat>IP client support

First version of Sat>IP client support.
Tested with DVB-S/S2 but not with DVB-C and DVB-T/T2.
DVB-S/S2 is tested with minisatip and TELESTAR Digibit box.
LNB selection with DiSEqC is not yet supported, only direct LNB connections.
Channel scanning works although less reliable than with /dev/dvb tuners.
EIT does work and making recordings does work. Live TV can be an issue.

Refs #13121

comment:10 Changed 12 months ago by Klaas de Waal <kdewaal@…>

In 18e7ec722/mythtv:

Add missing C++ include

Added C++ include <thread> for std::this_thread.

Refs #13121

comment:11 Changed 12 months ago by Mike Bibbings

Klaas,

mythconverg database schema update is required to add SatIP Recorder to profilegroups with associated entries in recordingprofiles otherwise mythbackend reports errors like :

Jul 17 11:20:53 2004-satip mythbackend: mythbackend[5769]: E Scheduler tv_rec.cpp:4159 (LoadProfile) TVRec[1]: Profile 'Default' not found, and unable to load fallback profile 'Default'.  Results may be unpredicable
Jul 17 11:20:53 2004-satip mythbackend: mythbackend[5769]: E TVRecEvent tv_rec.cpp:4159 (LoadProfile) TVRec[1]: Profile 'Live TV' not found, and unable to load fallback profile 'Default'.  Results may be unpredicable
Jul 17 11:20:55 2004-satip mythbackend: mythbackend[5769]: E TVRecEvent tv_rec.cpp:4159 (LoadProfile) TVRec[1]: Profile 'Default' not found, and unable to load fallback profile 'Default'.  Results may be unpredicable

Manually adding the following to the database stopped the error messages above.

direct to database INSERT INTO profilegroups SET name = 'SatIP Recorder', cardtype = 'SATIP', is_default = 1;
Note the id created in this case 19
INSERT INTO recordingprofiles SET name = "Default", profilegroup = 19;
INSERT INTO recordingprofiles SET name = "Live TV", profilegroup = 19;
INSERT INTO recordingprofiles SET name = "High Quality", profilegroup = 19;
INSERT INTO recordingprofiles SET name = "Low Quality", profilegroup = 19;

see dbcheck.cpp dbver == "1339" for an example using Vbox

$SCHEMA_VERSION in mythtv/binding/perl/MythTV.pm and mythtv/bindings/python/MythTV/static.py will also need updating to next schema version.

Mike

comment:12 Changed 12 months ago by Klaas de Waal <kdewaal@…>

In 379584c73a/mythtv:

Sat>IP Multirec support

Added Multirec to the Sat>IP client support, along the lines on how it is done for HDHomeRun. Tested with minisatip on Astra-2 satellite.

Refs #13121

comment:13 Changed 12 months ago by Klaas de Waal

Mike,

Thanks for the testing and for the tips. Expect fixes in the near future.

Issues not solved yet:

DVB-T2 tuning parameters
Recording profiles (was this not something from the PVR150/500 days, setting MPEG encoding parameters?)
MPTS full TS recording; described in the Sat>IP protocol but not yet implemented.

As yet untested:

DVB-C with minisatip

There are also still some stability issues with the TELESTAR Digibit satellite box.

comment:14 Changed 12 months ago by Mike Bibbings

Hi Klaas,

I am seeing a mythbackend seg fault on exit from LiveTV

Attached are gdb.txt and mythbackend log relating to the backtrace. I suspect it has something to do with the change that added SATIP to void TVRec::CloseChannel?(void) in tv_rec.cpp

Please attach all output as a file in bug reports.
MythTV Version : v32-Pre-699-g0db4df0b2f
MythTV Branch : master
Network Protocol : 91
Library API : 32.20200101-1
QT Version : 5.9.5
Options compiled in:
 linux profile use_hidesyms using_alsa using_oss using_pulse using_pulseoutput using_backend using_bindings_perl using_bindings_python using_bindings_php using_dvb using_firewire using_frontend using_hdhomerun using_satip using_vbox using_ceton using_hdpvr using_ivtv using_joystick_menu using_libcec using_libcrypto using_gnutls using_libdns_sd using_libfftw3 using_libxml2 using_lirc using_mheg using_opengl using_egl using_qtwebkit using_qtscript using_qtdbus using_taglib using_v4l2 using_v4l2prime using_x11 using_libbluray_external using_xrandr using_profiletype using_systemd_notify using_systemd_journal using_drm using_bindings_perl using_bindings_python using_bindings_php using_freetype2 using_mythtranscode using_opengl using_egl using_drm using_vaapi using_nvdec using_vdpau using_ffmpeg_threads using_mheg using_libass using_libxml2

Changed 12 months ago by Mike Bibbings

Attachment:	gdb.txt added

gdb.txt backtrace seg fault

Changed 12 months ago by Mike Bibbings

Attachment:	mythbackend.20200719123309.24920.log added

mythbackend log

comment:15 Changed 12 months ago by Mike Bibbings

At end of mythbackend.log there are some suspicious messages relating to QT timers and socket operations.

2020-07-19 13:33:57.375449 D [24920/24937] TVRecEvent recorders/streamhandler.cpp:155 (Stop) - SH[1](uuid:11223344-9999-0000-b7ae-c8600014a53d:DVBS2:0): Stopping
2020-07-19 13:33:57.375451 D [24920/24937] TVRecEvent recorders/streamhandler.cpp:158 (Stop) - SH[1](uuid:11223344-9999-0000-b7ae-c8600014a53d:DVBS2:0): Stopped
2020-07-19 13:33:57.375459 I [24920/24937] TVRecEvent mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Socket notifiers cannot be enabled or disabled from 
another thread
2020-07-19 13:33:57.375472 I [24920/24937] TVRecEvent mythcommandlineparser.cpp:2643 (operator()) - Qt: QObject::~QObject: Timers cannot be stopped from another thread
2020-07-19 13:33:57.375474 I [24920/24937] TVRecEvent mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Socket notifiers cannot be enabled or disabled from 
another thread
2020-07-19 13:33:57.375516 I [24920/24937] TVRecEvent tv_rec.cpp:3638 (TuningShutdowns) - TVRec[1]: Tearing down RingBuffer
2020-07-19 13:33:57.375602 I [24920/24937] TVRecEvent tv_rec.cpp:4438 (ClearFlags) - TVRec[1]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:3644
2020-07-19 13:33:57.375602 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 24 and type 'Read', disabling...
2020-07-19 13:33:57.375609 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 25 and type 'Read', disabling...
2020-07-19 13:33:57.375626 D [24920/24948] ProcessRequest livetvchain.cpp:34 (~LiveTVChain) - LiveTVChain(live-mike-GL62-7QF-2020-07-19T12:33:48Z): dtor
2020-07-19 13:33:57.375689 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 24 and type 'Read', disabling...
2020-07-19 13:33:57.375692 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 25 and type 'Read', disabling...
2020-07-19 13:33:57.375710 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 24 and type 'Read', disabling...
2020-07-19 13:33:57.375713 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 25 and type 'Read', disabling...
2020-07-19 13:33:57.375718 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 24 and type 'Read', disabling...
2020-07-19 13:33:57.375720 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 25 and type 'Read', disabling...
2020-07-19 13:33:57.375723 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 24 and type 'Read', disabling...
2020-07-19 13:33:57.375724 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 25 and type 'Read', disabling...
2020-07-19 13:33:57.375728 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 24 and type 'Read', disabling...
2020-07-19 13:33:57.375729 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 25 and type 'Read', disabling...
2020-07-19 13:33:57.375733 I [24920/24920] CoreContext mythcommandlineparser.cpp:2643 (operator()) - Qt: QSocketNotifier: Invalid socket 24 and type 'Read', disabling...
:

comment:16 Changed 12 months ago by Klaas de Waal <kdewaal@…>

In 55432fdd4/mythtv:

Sat>IP add EIT checkbox

Add EIT checkbox to enable/disable EIT scanning.
Add tuner type SATIP to TVRec::CloseChannel?.

Refs #13121

comment:17 Changed 12 months ago by Klaas de Waal <kdewaal@…>

In 0448b6f9e/mythtv:

Add profile group for Sat>IP recorder

Add profile group and recording profiles for the Sat>IP recorder.
Increase database version to 1364.

Refs #13121

comment:18 Changed 12 months ago by Klaas de Waal <kdewaal@…>

In 1d56b04ef7/mythtv:

Sat>IP DVB-T2 tuning parameters

Completed the DVB-T2 tuning parameter string representations.
Use "auto" for all parameters that are not known.
This is not specified in the Sat>IP specification but it does
specify that all unknown values are to be ignored in which
case the server can do what it thinks best.

Refs #13121

comment:19 Changed 12 months ago by Mike Bibbings

TEARDOWN is sending extraneous ? character after stream identifier:

2020-07-25 17:08:02.306141 D [27761/27801] Scanner recorders/satiprtsp.cpp:235 (sendMessage) - SatIPRTSP[1]: sendMessage write: TEARDOWN rtsp://192.168.0.202:554/stream=1? RTSP/1.0

Change in satiprtsp.cpp see 20200726_satip_teardown.patch

Changed 12 months ago by Mike Bibbings

Attachment:	20200726_satip_teardown.patch added

Teardown patch

comment:20 Changed 12 months ago by Mike Bibbings <mike.bibbings@…>

In 45ed62ad9c/mythtv:

Remove extraneous ? character in Sat>IP TEARDOWN message

Refs #13121

Signed-off-by: Klaas de Waal <kdewaal@…>

comment:21 Changed 12 months ago by Mike Bibbings

I am seeing on occasion mythtv-setup seg faulting whilst channel scanning on DVB-T/T2 (UK Freeview)

Attached are gdb backtrace and mythtv-setup log.

In this case minisatip is running remote to mythtvbackend on a Raspberry Pi3 with TVHAT tuner which has the following capabilities:

pi@pi3-20200724:~/build/w_scan2 $ dvb-fe-tool
Device Sony CXD2880 (/dev/dvb/adapter0/frontend0) capabilities:
     CAN_2G_MODULATION
     CAN_FEC_1_2
     CAN_FEC_2_3
     CAN_FEC_3_4
     CAN_FEC_4_5
     CAN_FEC_5_6
     CAN_FEC_7_8
     CAN_FEC_AUTO
     CAN_GUARD_INTERVAL_AUTO
     CAN_INVERSION_AUTO
     CAN_MUTE_TS
     CAN_QAM_16
     CAN_QAM_32
     CAN_QAM_64
     CAN_QAM_128
     CAN_QAM_256
     CAN_QAM_AUTO
     CAN_QPSK
     CAN_RECOVER
     CAN_TRANSMISSION_MODE_AUTO
DVB API Version 5.11, Current v5 delivery system: DVBT2
Supported delivery systems:
     DVBT
    [DVBT2]
Frequency range for the current standard:
From:             174 MHz
To:               862 MHz
Step:            1.00 kHz

Changed 12 months ago by Mike Bibbings

Attachment:	gdb.2.txt added

backtrace chanscan seg fault

Changed 12 months ago by Mike Bibbings

Attachment:	mythtv-setup.20200730131428.19054.log.zip added

mythtv-setup log chanscan seg fault

comment:22 Changed 12 months ago by Klaas de Waal <kdewaal@…>

In b2672ec3a/mythtv:

Sat>IP client KeepAlive? timer

Improve the RTSP KeepAlive? timer handling, inspired by how it is done in the Ceton RTSP handler.

Refs #13121

comment:23 Changed 12 months ago by Klaas de Waal

Hi Mike,

The above patch does solve a stability issue that came up when stress testing with a local DVB-S minisatip and a real networked Sat>IP box, also DVB-S.

However, your DVB-T2 scanning crash does look different. The plan is to reproduce this by attaching a MyGica? USB stick to a RPi3 and run minisatip on that. I do not expect that the hat does make any difference.

N.B. If there is any special incantation for the minisatip that you use please post that also.

comment:24 Changed 12 months ago by Mike Bibbings

Hi Klaas,

Nothing special for minisatip on Pi3, invoked at default by sudo ./minisatip

built from master source https://github.com/catalinii/minisatip

minisatip configuration


Linux DVB:				  enabled
Common Interface (needs DVBEN50221):	  disabled
OpenSSL (AES as part of DVBAPI):	  enabled
Embedded system:			  disabled
DVBCSA (needs libdvbcsa):		  disabled
Netceiver support:			  disabled
SatIP Client:				  enabled
Static:					  disabled
dvbapi:					  enabled
axe:					  disabled
enigma:					  disabled

I use the same default minisatip build and configuration everywhere including Xubuntu 18.04 and Xubuntu 20.04

Mike

comment:25 Changed 12 months ago by Klaas de Waal

The segfault when scanning for DVB-T2 channels can be now reproduced, with the MyGica? USB stick and minisatip in my development box. To be continued.

comment:26 Changed 12 months ago by Klaas de Waal <kdewaal@…>

In 2daf1a046a/mythtv:

Sat>IP client -- Discard old RTP packets

After tuning to a new channel discard all RTP packets received before the new channel is
tuned and the PLAY command is given with at least one pid.
Do not process any RTP packet after a TEARDOWN command is given.

Refs #13121

comment:27 Changed 12 months ago by Mike Bibbings

Hi Klaas,

I am still seeing mythtv-setup seq fault whilst channel scanning on UK Freeview (DVB/T-T2) with latest master e015e7a. In this case it is a TBS6280 tuner with minisatip on same machine.

Attached are mythtv-setup.log and associated gdb backtrace. Note the seg fault happened after a number of channel scans (full scan).

Mike

Changed 12 months ago by Mike Bibbings

Attachment:	mythtv-setup.20200809123425.79080.log.zip added

mythtv-setup log tbs6280

Changed 12 months ago by Mike Bibbings

Attachment:	gdb-tbs6280.txt added

gdb backtrace tbs6280

comment:28 Changed 12 months ago by Klaas de Waal

Hi Mike,

Thanks for testing, looks like this is the same crash as before. So the discarding of old packets does not solve it, only makes the problem less frequent. Looks like a concurrency/locking issue as valgrind does not show anything.

Other bugs that are still present:

When configured with a single tuner instance and Schedule as Group disabled, then the backend crashes on EIT when the single tuner instance is closed. This is accompanied with Qt error messages about doing things in the wrong thread. Removing SATIP from the close in tv_rec.cpp, or having at least two tuner instances, does fix this for now.
Channelscan timeouts while actually finding all the channels.

Have been testing with minisatip and DVB-C and that works OK.

To be continued.

comment:29 Changed 11 months ago by peper03

Hi Klaas,

I had a bit of time to play around with this and immediately hit the two bugs you mentioned.

I've not managed to find a solution to them but thought I'd add what I've found so far:

The crash appears to be because SatIPChannel::Open is called in ChannelBase::CreateChannel? via TVRec::CreateChannel? at start-up in the main thread, but SatIPChannel::Close is called from the TVRec thread when the recording. This is what is causing the error messages about the wrong threads and appears to be what is leading to the SIGSEGV.

ChannelBase::CreateChannel? almost immediately closes the channel if it's DVB, HDHOMERUN or a V4L card, but not if it's SatIP. Adding SatIP here stops the recording even starting and I haven't had time to investigate why.

Regarding the channel scan, I'm not sure if it's the same issue you are seeing but I had to tell it to use only DVB-S instead of DVB-S2 before the scan would work. The DVB-S2 channels were still found and a brief look in Wireshark seemed to indicate that MPEG-TS packets were being received when DVB-S2 was selected but nothing appeared in mythtv-setup and it timed out on the first transponder.

comment:30 Changed 11 months ago by Klaas de Waal

Hi Richard,

Thanks for looking into this. You are completely right about the bits in ChannelBase?, I had overlooked this. Getting the recording to start again after the channel has been closed in ChannelBase? is being fixed.

What is still going wrong in the channel scan is timeouts. They are almost all caused by, after doing the tuning, receiving a PAT from the previously tuned frequency. Tuning is complete when all PMTs of all channels have been received and this then never happens. How to filter out the packets from the previous frequency is still an issue. One possibility is to check more on transport ID if that is known, but this is a biggish change to the common code and not limited to SatIP.

About DVB-S/S2, in the "Full Scan (Tuned)" you have to specify the delivery system and the other tuning parameters of the initial frequency you want to start with.

comment:31 Changed 11 months ago by Klaas de Waal <kdewaal@…>

In 00a94e00c1/mythtv:

Sat>IP client -- Limit number of pids in PLAY request

Limit the number of pids in a PLAY request to 32.
If the requested number of pids is higher then select all pids.
This selects then the complete transport stream without filtering.
Such a high number of pids only happens with channel scanning
when the PMT pids for all channels in the PAT are selected.
Testing with hardware Sat>IP box, the Telestar Digibit R1, shows
that this box becomes unhappy when the number of pids is too large.
The software minisatip implementation does not have this limit.
Note that the limit for the number of pids in the DVB code
in MythTV is 64. This is not enough for some transports found
on satellite Astra-1 on 19.2E.

Refs #13121

comment:32 Changed 11 months ago by Klaas de Waal <kdewaal@…>

In d6e04a4e8a/mythtv:

Sat>IP client -- Reset tuner lock status

Reset tuner lock status after TEARDOWN and SETUP messages.
This prevents accessing the pid handling code with the list of pids from the previous channel when there is no tuner lock.

Refs #13121

comment:33 Changed 11 months ago by Klaas de Waal <kdewaal@…>

In 027f1291b/mythtv:

Sat>IP client -- Never close channel

Keep the channel always open.
This avoids a Qt issue about opening and closing in different threads that only
happens when "Max Recordings" is set to 1 and the "Schedule as Group" is unchecked.
A more elegant solution would be to insure that opening and closing happens always
in the same thread like it is done in the ceton driver.

Refs #13121

comment:34 Changed 11 months ago by Klaas de Waal <kdewaal@…>

In cf09ffe847/mythtv:

Sat>IP client -- Add recording of MPTS streams

Add the capability to record a full transport stream, similar to how it is done for the HDHomeRun tuners.
Reduce the interval to wait before processing received RTP packets from 200 to 20 milliseconds.
This greatly reduces the number of missed RTP packets and the corresponding "Sequence number" error messages.

Refs #13121

comment:35 Changed 11 months ago by Klaas de Waal <kdewaal@…>

In 728b5a68d/mythtv:

Sat>IP client -- Fix compilation warning

Fix compilation warning introduced with the MPTS patch.

Refs #13121

comment:36 Changed 11 months ago by Klaas de Waal <kdewaal@…>

In d9589fd1de/mythtv:

Sat>IP client -- Remove unused variables

Removed two unused variables and other cosmetic cleanup.

Refs #13121

comment:37 Changed 11 months ago by Klaas de Waal

Current status:

Supports DVB-C/T/T2/S/S2
Does NOT support DiSeqC yet
Supports channel scans
Tested with minisatip (DVB-C/T2/S/S2) and with the Telebit Digibit R1 box (DVB-S/S2)
No crashes observed for some time now

Implementation details that might be improved:

Open/close code. Channels are always kept open because opening and closing gives all kinds of errors.
Reducing the RTP packet processing interval from 200 to 20 ms does fix a problem with missing RTP packets in MPTS recordings but there is no logical reason why this should make a difference. A possible reason can be the implementation of the underlying packetbuffer code because random numbers are used to identify packets and there is always a risk of collusion when storing a large number of packets.
Channel scans work OK but sometimes the PAT of the previous transport is processed. This does cause a timeout but the scan results are OK. The difficult part is here that MythTV assumes that as soon as a tuning command is given that everything that is received after that is from the requested frequency. This is not really true in networked environments where packets are buffered. One possible solution, which would improve scanning for all tuner types, is to filter on transport ID when that is known. This requires storage of the transport ID in table dtv_multiplex and it somehow changes the concept of tuning from tuning to a frequency into tuning to a transport ID.
Tuning timeout default values are quite high and are correct for DVB-S/S2 but could be reduced for DVB-C and DVB-T2. The actual values can of course be configured in the Capture Card page of mythtv-setup.

comment:38 Changed 8 months ago by jksj461

I have tried a Telestar Digibit Twin but could only get one input to work and then with some packet loss. I have posted some log fragments in https://forum.mythtv.org/viewtopic.php?f=3&t=4102. It looks to me like the box is defective so I am not posting here as a fault. I will return it in the next few days. I can supply more log info if you think it is a genuine bug rather than defective hardware.

comment:39 Changed 8 months ago by jksj461

Testing with a Digibit R1- produces good results with 2 active inputs. Log shows good quality recordings with some but low packet loss

tv_rec.cpp:825 (FinishedRecording) TVRec[3]: FinishedRecording(65791_2020-11-21T00:05:00Z) good recq:<RecordingQuality overall_score="1" key="65791_2020-11-21T00:05:00Z" continuity_error_count="10" packet_count="19911688" />

I use a remote frontend so the network may be busy occasionally. If I up the number of inputs in use to 3 and add EPG, noticeable glitches appear on the display about every 10 mins. My question is have you tested using the standard firmware in the Digibit box :- Firmware Version V1.25.0.157 (30-03-2016 17:48) or are you using https://github.com/perexg/satip-axe.

I note that satip-axe is an implementation of minisatip which supports TCP streaming. If I switch to this firmware would the mythtv client work with TCP streams and do you think it would be a sensible solution.

comment:40 Changed 8 months ago by Klaas de Waal

I have not changed the firmware in the box and it is indeed "Firmware Version V1.25.0.157 (30-03-2016 17:48)". I have tested with two inputs simultaneously and as noted, this works OK.

However, I found a correlation between "Sequence errors", indicating RTP packet loss and consequently continuity errors, and EIT "write to disk" actions. This could be the cause of the periodic display glitches.

MythTV only supports UDP at the moment. Minisatip can do both UPD and TCP and maybe going TCP is the way forward, but for the moment the plan is to check the UDP packet handling.

comment:41 Changed 8 months ago by Klaas de Waal

Testing with the SatIP box the "Sequence errors", other than those that appear after tuning to a new channel, are almost all gone when the UDP kernel buffers are increased from 256kb, the default on my system, to 4Mb.

This can be effected with the following commands:

$ sudo sysctl -w net.core.rmem_max=4194304
net.core.rmem_max = 4194304
$ sudo sysctl -w net.core.rmem_default=4194304
net.core.rmem_default = 4194304

Investigation shows that the data is not lost in satiprtsp.cpp; all packets that are received from the UDPSocket are stored in the buffer and retrieved from the buffer without loss.

There are also no lost packets at the interface level; the network driver has no errors and network statistics do not show lost packets.

Therefore all packets are lost in the UDP buffers; the packets are simply not read on time by MythTV. This is demonstrated by the output of

cat /proc/net/udp

of which the last column is the number of packets lost.

Increasing the buffer size does give more latency. A full transport stream from a satellite is about 40Mbit/second which is 5Myte/second, so 4Mb buffering is 800 milliseconds.

I do not know how much buffer memory is used by the /dev/dvb/adapter*/* drivers but mythtv is capable of reading all data from these devices without loss.

Using TCP instead of UDP will not solve anything as the packets are not lost at the network level. TCP allows flow control between MythTV and the SatIP box but the SatIP box will be less capable of buffering the stream than the MythTV PC is.

Note that usually the PID filtering is done by the SatIP box; only when the number of PIDs is more than 30 the full transport stream is received. This is the worst case situation and this can happen with channel scanning on some streams. Normal recording always uses PID filtering by the SatIP box and then the 4Mbyte buffer should be big enough for perfect recordings.

comment:42 Changed 8 months ago by Klaas de Waal

Increase UDP buffer size for Sat>IP

Try to increase the UDP buffer size for reading the Sat>IP RTP streams to 8Mbytes (decimal). A log message is given when the system maximum only allows for a lower value. Change log messages to have only the cardid and not the device name on each message. This leaves more space for the actual message text.

Commit f0c708a89a3b762fa3ccbe3d8ccede7745000649

comment:43 Changed 8 months ago by jksj461

Have not yet tried the above commit. Will do so shortly. However by increasing the number of udp buffers in the system I can now record 3 HD streams with no packet loss. This is a big improvement will test further https://medium.com/@CameronSparr/increase-os-udp-buffers-to-improve-performance-51d167bb1360 .Used

If the values are less than 26214400 bytes (25MB) you should add the following lines to the /etc/sysctl.conf file:

net.core.rmem_max=26214400
net.core.rmem_default=26214400

comment:44 Changed 8 months ago by jksj461

Apologies I had not noticed that you had already posted on the benefits of increasing the UDP buffering. Having increased the buffering and taken f0c708a89a3b762fa3ccbe3d8ccede7745000649 the system is performing well. There was a bad patch yesterday when :-

continuity_error_count="4409" packet_count="21125940"

This bad patch occurred in the last 5 minutes of the recording on BBC One HD - in the overrun time (in the 5 mins after the recording was scheduled to finish). It occurs to me that this was because 'schedule as group' is the default settings in mythtv-setup. So a new recording had been started in parallel on that tuner while the old one was completing its overun time.

I have now removed schedule as group from all the capture card inputs which I think will improve stability.

According to the 'monitor' page of the Digibit, normal HD channels show average rates up to 10000Kbits average. However I am now running

SatIPSH[6](uuid:3eec0475-c365-44e7-bf7c-6d53b0daf8e4:DVBS2:1): Tune url:rtsp://192.168.0.44:554/?fe=2&freq=10847.00&pol=v&ro=0.20&msys=dvbs2&mtype=8psk&sr=23000&fec=34&plts=auto

is showing 50000Kbits average. The BBC One / Two HD mux seems to go straight to 50k independently of how many channels are being viewed.

I have now ditched my USB tuner and am using 3 inputs from the Digibox and it is working great including EPG many thanks.

comment:45 Changed 8 months ago by Klaas de Waal

Thanks for reporting back.

About the UDP buffer size. I've looked in the HDHomeRun library and there the UDP buffer size is set to 1024x1024 bytes, the actual value depending on the net.core.rmem_max value of the system. Note that it overall saves memory if you only set the net.core.rmem_max value and not the net.core.rmem_default because MythTV only extends the buffer size for the socket that is actually used for the video data stream. There is also a socket for the control data and the buffer size of that socket does not need to be changed.

I've looked into the "bad patch" problem and this is caused by the multirec feature not yet being implemented completely. What happens is that when your second recording starts the box is tuned again, on the same channel. This causes the disruption in your first recording. The correct behavior is to recognize that the channel is already in use and that it is already correctly tuned so the tuning can be skipped. This is how it is implemented for the /dev/dvb/adapter*/* devices (PCI/PCIe, USB) and this is also how it should be done for SatIP.

About the bitrate of the incoming stream. The code is now such that when more than 32 PIDs are requested the full transport stream is received. When there are less PIDs requested then the Sat>IP box is doing the PID filtering so then you only receive the PIDs that are needed. This is done because the Digibit R1 box effectively dies when your request more than 36 or 37 PIDs. The minisatip software, running on a PC, does not have this limitation but we write software for the worst case situation. Still to investigate why recording a channel on the BBC One/Two? HD mux requires so many PIDS that it needs to receive the full transport stream.

Changed 8 months ago by jksj461

Attachment:	DroppedPacketLog02-12-20.zip added

comment:46 Changed 8 months ago by jksj461

Had 5 problem free days running 3 tuners and schedule as group disabled. Allowing two recordings on the first tuner to benefit from BBc One & Two Hd being on the same mux. This should not work for the reasons you describe.

+--------+-------------+-------------+-----------+------------+-------------+-------------+
| cardid | displayname | recpriority | quicktune | schedorder | livetvorder | dvb_eitscan |
+--------+-------------+-------------+-----------+------------+-------------+-------------+
|      1 | Frs1        |           4 |         0 |          1 |           1 |           1 |
|      2 | Frs2        |           3 |         0 |          1 |           1 |           0 |
|      3 | Frs3        |           2 |         0 |          1 |           1 |           0 |
|      4 | Frs1        |           4 |         0 |          1 |           1 |           1 |
+--------+-------------+-------------+-----------+------------+-------------+-------------+

So connected all 4 inputs to the LNB and ran the system with only one recording allowed per card. This fell over at the transition time 9 pm again with lots of drop packets. A log is attached - it may be noteworthy that there is no tuning attempt for the program Harlots at 9 pm it must be trying to attach to an existing stream. Restarted the backend after 4 mins and it did the same thing again straight away ... mystified. Went back to my original configuration 3 inputs with two recordings allowed on the first. Seems bomb proof have been soak testing it ever since wth every sort of transition I can find between one or two recordings on the first tuner.

Log file added to attachments - apologies seems to have been attached to previous post? Just incompetance.

comment:47 follow-up: 49 Changed 8 months ago by Klaas de Waal

Again thanks for testing!

The latest update, commit f5e0fc0cf812b7615d571ef217e50229301bd5ef, skips the tuning part if you have a second recording on the same multiplex and thus avoids the "Sequence error" and the associated packet loss.

Next step is that the SatIP implementation will be restructured along the lines of how the HDHomeRun support is implemented. This is a comparable device, with four independent tuners and use of UDP packets for the video streaming. The HDHomeRun works OK with only a 1Mbyte UDP input buffer (instead of 8Mbyte) and it does not do extra buffering at the input. The current SatIP implementation is largely inspired by how it is done for Ceton and IPTV.

This should fix the remaining issues:

inefficient/slow due to buffering all received input data
allow to close the input device when not in use
allow restart of the backend

comment:48 Changed 8 months ago by jksj461

The current implementation is performing very well many thanks. I will test anything you commit.

comment:49 in reply to: 47 Changed 8 months ago by gigem

Replying to Klaas de Waal:

Next step is that the SatIP implementation will be restructured along the lines of how the HDHomeRun support is implemented. This is a comparable device, with four independent tuners and use of UDP packets for the video streaming. The HDHomeRun works OK with only a 1Mbyte UDP input buffer (instead of 8Mbyte) and it does not do extra buffering at the input. The current SatIP implementation is largely inspired by how it is done for Ceton and IPTV.

Klaas, FYI, I had a serious problem this past summer with frequent corruption in most recordings. With help, I traced the problem to lack of buffer space for my HDHR and Ceton tuners. I suspected a Linux kernel change was to blame as I'd never had the problem before and I don't believe the MythTV recorders had changed. Regardless of the cause, I raised my HDRingbufferSize setting to 75200 to get rid of the corruption. I have plenty of memory in my backend so I didn't spend any time backing that value down to see how low it could go without causing the problem.

Do the SatIP devices support TCP? From what I have gathered from other, HDHR users, using TCP does not have the same buffering problem and is also the recommended, access method from SiliconDust?. If the SaiIP boxes support TCP, you should consider using it, at least optionally.

comment:50 Changed 7 months ago by jksj461

mythbackend version: (HEAD detached at 7de9c58ad4) [v32-Pre-1753-g7de9c58ad4] www.mythtv.org

Had faultless recordings for the last 4 weeks until last night. I think that attempting to record more than one program on the same mux causes tuning problems where only a single channel is allowed. The above condition is unlikely to occur within my configuration so the above failure may be the only occurrence within the period. The issue arises probably due to me over constraining the configuration to get deterministic behaviour. I allow two simultaneous recording off the first mux and constrain the rest to one. This normally works fine as BBC1/2 HD are the lowest channel numbers and are normally allocated to this first mux. In the case in question the first mux was already allocated. Do you recommend me setting Schedule as Group for all tuners or setting max recordings to 2 for all tuners (which do you use).

Dec 31 22:24:30  I TVRecEvent tv_rec.cpp:1620 (HandlePendingRecordings) TVRec[2]: ASK_RECORDING 2 29 0 0
Dec 31 22:25:00  I TVRecEvent tv_rec.cpp:1061 (HandleStateChange) TVRec[2]: Changing from None to RecordingOnly
Dec 31 22:25:00  I TVRecEvent mythdbcon.cpp:419 (PurgeIdleConnections) New DB connection, total: 11
Dec 31 22:25:00  I TVRecEvent tv_rec.cpp:3661 (TuningFrequency) TVRec[2]: TuningFrequency
Dec 31 22:25:00  I TVRecEvent recorders/satipstreamhandler.cpp:216 (Tune) SatIPSH[2]: Tune 10847000
Dec 31 22:25:00  I Scheduler scheduler.cpp:2889 (HandleRecordingStatusChange) Tuning recording: "The Graham Norton New Year's Eve Show": channel 65792 on cardid [2], sourceid 1
Dec 31 22:25:00  C CoreContext programinfo.cpp:252 (ProgramInfo) ProgramInfo(): Failed to find recorded entry for 0.
Dec 31 22:25:01  I CoreContext scheduler.cpp:713 (UpdateRecStatus) Updating status for "The Graham Norton New Year's Eve Show" on cardid [2] (Tuning => Recording)
Dec 31 22:25:01  I TVRecEvent tv_rec.cpp:4208 (TuningNewRecorder) TVRec[2]: rec->GetPathname(): '/media/library/TV/65792_20201231222500.ts'
Dec 31 22:25:01  I TVRecEvent tv_rec.cpp:4241 (TuningNewRecorder) TVRec[2]: TuningNewRecorder - CreateRecorder()
Dec 31 22:25:01  E TVRecEvent recorders/recorderbase.cpp:216 (SetStrOption) RecBase[2](uuid:3eec0475-c365-44e7-bf7c-6d53b0daf8e4:DVBS2:2): SetStrOption(...recordingtype): Option not in profile.

Dec 31 22:44:31  I TVRecEvent tv_rec.cpp:1620 (HandlePendingRecordings) TVRec[3]: ASK_RECORDING 3 29 0 0
Dec 31 22:45:00  I TVRecEvent tv_rec.cpp:1061 (HandleStateChange) TVRec[3]: Changing from None to RecordingOnly
Dec 31 22:45:00  I TVRecEvent mythdbcon.cpp:419 (PurgeIdleConnections) New DB connection, total: 14
Dec 31 22:45:00  I TVRecEvent tv_rec.cpp:3661 (TuningFrequency) TVRec[3]: TuningFrequency
Dec 31 22:45:00  I TVRecEvent recorders/satipstreamhandler.cpp:216 (Tune) SatIPSH[3]: Tune 10847000
Dec 31 22:45:00  I Scheduler scheduler.cpp:2889 (HandleRecordingStatusChange) Tuning recording: "Mock the Week": channel 65791 on cardid [3], sourceid 1
Dec 31 22:45:00  N Scheduler scheduler.cpp:3246 (HandleIdleShutdown) Blocking shutdown because of an active encoder
Dec 31 22:45:00  N Scheduler scheduler.cpp:3257 (HandleIdleShutdown) Blocking shutdown because of delay request from external application
Dec 31 22:45:00  C CoreContext programinfo.cpp:252 (ProgramInfo) ProgramInfo(): Failed to find recorded entry for 0.
Dec 31 22:45:01  I CoreContext scheduler.cpp:713 (UpdateRecStatus) Updating status for "Mock the Week" on cardid [3] (Tuning => Recording)
Dec 31 22:45:01  I TVRecEvent tv_rec.cpp:4208 (TuningNewRecorder) TVRec[3]: rec->GetPathname(): '/media/library/TV/65791_20201231224500.ts'
Dec 31 22:45:01  I TVRecEvent tv_rec.cpp:4241 (TuningNewRecorder) TVRec[3]: TuningNewRecorder - CreateRecorder()
Dec 31 22:45:01  E TVRecEvent recorders/recorderbase.cpp:216 (SetStrOption) RecBase[3](uuid:3eec0475-c365-44e7-bf7c-6d53b0daf8e4:DVBS2:3): SetStrOption(...recordingtype): Option not in profile.

Dec 31 23:20:00  I TVRecEvent tv_rec.cpp:1061 (HandleStateChange) TVRec[3]: Changing from RecordingOnly to None
Dec 31 23:20:01  N RecThread recorders/recorderbase.cpp:491 (FinishRecording) Finished Recording: Container: MPEG2-TS Video Codec: h264 (1920x1088 A/R: 3 25fps) Audio Codec: ac3
Dec 31 23:20:01  I TVRecEvent tv_rec.cpp:825 (FinishedRecording) TVRec[3]: FinishedRecording(65791_2020-12-31T22:45:00Z) damaged recq:<RecordingQuality overall_score="0.8" key="65791_2020-12-31T22:45:00Z" continuity_error_count="25014" packet_count="10025590" />
Dec 31 23:20:02  I CoreContext scheduler.cpp:713 (UpdateRecStatus) Updating status for "Mock the Week" on cardid [3] (Recording => Recorder Failed)
Dec 31 23:20:02  I Scheduler scheduler.cpp:2321 (HandleReschedule) Reschedule requested for CHECK -9 7289 0 UpdateRecStatus2 | Mock the Week |  | Dara O Briain and Hugh Dennis are joined by an array of guests in a special edition of the show. Contains some strong language. | fp.bbc.co.uk/m/ek0u
Dec 31 23:20:02  I Scheduler scheduler.cpp:2438 (HandleReschedule) Scheduled 79 items in 0.1 = 0.00 match + 0.01 check + 0.11 place
Dec 31 23:20:02  I ProcessRequest mainserver.cpp:1801 (HandleAnnounce) MainServer: MainServer::ANN Playback
Dec 31 23:20:02  I ProcessRequest mainserver.cpp:1803 (HandleAnnounce) MainServer: adding: tv(55ed2f0fec60) as a client (events: 0)
Dec 31 23:20:03  I ProcessRequest mainserver.cpp:1801 (HandleAnnounce) MainServer: MainServer::ANN Monitor
Dec 31 23:20:03  I ProcessRequest mainserver.cpp:1803 (HandleAnnounce) MainServer: adding: tv(55ed2ec63030) as a client (events: 1)
Dec 31 23:20:16  I MythSocketThread(75) mainserver.cpp:7845 (connectionClosed) Playback sock(55ed2f0fec60) 'tv' disconnected
Dec 31 23:20:16  I MythSocketThread(88) mainserver.cpp:7845 (connectionClosed) Monitor sock(55ed2ec63030) 'tv' disconnected
Dec 31 23:21:02  N Expire autoexpire.cpp:241 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 12.0 GB w/freq: 7 min
Dec 31 23:23:20  N HttpServer70 services/myth.cpp:950 (DelayShutdown) Shutdown delayed 5 minutes for external application.
Dec 31 23:27:20  N HttpServer70 services/myth.cpp:950 (DelayShutdown) Shutdown delayed 5 minutes for external application.
Dec 31 23:28:02  N Expire autoexpire.cpp:241 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 12.0 GB w/freq: 7 min
Dec 31 23:30:00  N Scheduler scheduler.cpp:3246 (HandleIdleShutdown) Blocking shutdown because of an active encoder
Dec 31 23:30:00  N Scheduler scheduler.cpp:3253 (HandleIdleShutdown) Blocking shutdown because of active jobs
Dec 31 23:30:00  N Scheduler scheduler.cpp:3257 (HandleIdleShutdown) Blocking shutdown because of delay request from external application
Dec 31 23:30:08  I Metadata_20880 jobqueue.cpp:2196 (DoMetadataLookupThread) JobQueue: Metadata Lookup Starting for "The Graham Norton New Year's Eve Show" recorded from channel 65792 at 2020-12-31T22:25:00Z
Dec 31 23:30:11  I ProcessRequest mainserver.cpp:1801 (HandleAnnounce) MainServer: MainServer::ANN Playback
Dec 31 23:30:11  I ProcessRequest mainserver.cpp:1803 (HandleAnnounce) MainServer: adding: tv(55ed2ec65a50) as a client (events: 0)
Dec 31 23:30:11  I ProcessRequest mainserver.cpp:1801 (HandleAnnounce) MainServer: MainServer::ANN Monitor
Dec 31 23:30:11  I ProcessRequest mainserver.cpp:1803 (HandleAnnounce) MainServer: adding: tv(55ed2fc75f70) as a client (events: 1)
Dec 31 23:30:15  I MythSocketThread(70) mainserver.cpp:7845 (connectionClosed) Playback sock(55ed2ec65a50) 'tv' disconnected
Dec 31 23:30:15  I MythSocketThread(86) mainserver.cpp:7845 (connectionClosed) Monitor sock(55ed2fc75f70) 'tv' disconnected
Dec 31 23:30:35  I Scheduler scheduler.cpp:2321 (HandleReschedule) Reschedule requested for MATCH 0 1 0 2021-01-01T00:00:00Z EITScanner
Dec 31 23:30:35  I Scheduler scheduler.cpp:2438 (HandleReschedule) Scheduled 79 items in 0.2 = 0.07 match + 0.04 check + 0.11 place
Dec 31 23:31:20  N HttpServer59 services/myth.cpp:950 (DelayShutdown) Shutdown delayed 5 minutes for external application.
Dec 31 23:35:00  I TVRecEvent tv_rec.cpp:1061 (HandleStateChange) TVRec[2]: Changing from RecordingOnly to None
Dec 31 23:35:00  I RecThread mythdbcon.cpp:419 (PurgeIdleConnections) New DB connection, total: 13
Dec 31 23:35:00  N RecThread recorders/recorderbase.cpp:491 (FinishRecording) Finished Recording: Container: MPEG2-TS Video Codec: h264 (1920x1088 A/R: 3 25fps) Audio Codec: ac3
Dec 31 23:35:00  I TVRecEvent tv_rec.cpp:825 (FinishedRecording) TVRec[2]: FinishedRecording(65792_2020-12-31T22:25:00Z) damaged recq:<RecordingQuality overall_score="0.8" key="65792_2020-12-31T22:25:00Z" continuity_error_count="26445" packet_count="22679561" />
Dec 31 23:35:00  I CoreContext scheduler.cpp:713 (UpdateRecStatus) Updating status for "The Graham Norton New Year's Eve Show" on cardid [2] (Recording => Recorder Failed)
Dec 31 23:35:00  I Scheduler scheduler.cpp:2321 (HandleReschedule) Reschedule requested for CHECK -9 6760 0 UpdateRecStatus2 | The Graham Norton New Year's Eve Show |  | With Tom Hanks, Emily Blunt, Jamie Dornan, Hugh Fearnley-Whittingstall, Nish Kumar and Jessica Chastain. Sophie Ellis-Bextor performs Crying at the Discotheque. | fp.bbc.co.uk/m/eixn
Dec 31 23:35:00  I Scheduler scheduler.cpp:2438 (HandleReschedule) Scheduled 78 items in 0.1 = 0.00 match + 0.00 check + 0.10 place

comment:51 Changed 7 months ago by Klaas de Waal

It could be that your SatIP box has become unhappy. I have that incidentally when testing and then I reboot the box with the web interface.

I generally have the "Schedule as Group" enabled and then virtual tuners are created when needed. This does not change the load on the SatIP box that much, only a few additional PIDs are selected. There is a switchover point when more than 32 PIDs are selected; in that case all PIDs are received and all PID filtering is done by software somewhere. Note that this can already happen with a single channel, e.g. channel 101 "BBC One London" wants 36 PIDs.

When I test this with the Raspberry Pi 3B then it can get overloaded especially when it is doing EIT on the second input, which can also need the full transport stream. On a computer with a real 1Gb/s network interface this should not be a limitation.

In your configuration, with (IIRC) a number of inputs configured all to receive the same satellite, I would connect all inputs to the same video source, select "Schedule as Group" on all inputs and let the system figure it all out.

comment:52 Changed 7 months ago by jksj461

Thanks changed to use "Schedule as Group". Can't currently break it so great!. Currently trying to learn enough python to reset the Digibit when the backend is shutdown.

comment:53 Changed 5 months ago by jksj461

Just updated current master from v32-Pre-2005-g4ce4d36b2b to v32-Pre-2255-g37ef3848bd .

The first recording attempted was 30 mins but only the first minute was recorded.

Attempting other recordings showed the same problem. This is my production system so had to revert straight away. There is nothing obvious the system was looking for the recording to end at the expected time

Feb 12 18:35:00 tv mythbackend: mythbackend[11782]: I TVRecEvent tv_rec.cpp:823 (FinishedRecording?) TVRec[1]: FinishedRecording?(65792_2021-02-12T18:00:00Z) damaged recq:#012<RecordingQuality? overall_score="0" key="65792_2021-02-12T18:00:00Z" continuity_error_count="0" packet_count="361427">#012 <Gap start="2021-02-12T18:00:58Z" end="2021-02-12T18:30:00Z" duration="1741" />#012</RecordingQuality?>

Presumably the recent timer changes in Master have affected the sat-ip recorder.

Note that the input lights on the Digibit appeared to being extinguished much earlier than normal releasing those inputs. So time may have been affected in other ways than just recordings. Cannot be sure of this as I don't fully understand the normal behaviour, will attach log.

Changed 5 months ago by jksj461

Attachment:	ShortRecordings.txt added

comment:54 Changed 5 months ago by Klaas de Waal

I can confirm that with today's master Sat>IP is failing. Version 86d05b6d2c which is from 29 days ago, so before the std::chrono update, is still OK. I will look into this.

comment:55 Changed 5 months ago by Klaas de Waal

Fixed in commit 3cf00701ba08469c58f5e7e3b2e88fc38b621cc8.

comment:56 Changed 5 months ago by jksj461

Thanks for the quick fix much better but I had a zero byte recording for the first time ever using sat-ip when twp programs started at the same time. May be just a coincidence will test more in the morning.

I note that tuning fails at 21:00:04 implying that the timeout period is very short. Posting full log.

Having checked I note that 4 sec is the timeout setting. Looking back in the logs can certainly take 3 when multi recordings happen. Will test this morning.

14/02/21 09:30 Just started 4 simultaneous recordings, no issues and all happened in 1 second. Will test more leaving a couple of hours between events.

FebFeb 13 20:59:21 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:405 (timerEvent) SatIPRTSP[1]: Sending KeepAlive timer 4
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:289 (RecordPending) TVRec[1]: RecordPending on inputid [1]
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I Scheduler cardutil.cpp:2092 (GetConflictingInputs) CardUtil[1]: GetConflictingInputs(1) 4
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:289 (RecordPending) TVRec[4]: RecordPending on inputid [1]
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:289 (RecordPending) TVRec[2]: RecordPending on inputid [2]
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I Scheduler cardutil.cpp:2092 (GetConflictingInputs) CardUtil[2]: GetConflictingInputs(2) 5
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:289 (RecordPending) TVRec[5]: RecordPending on inputid [2]
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1623 (HandlePendingRecordings) TVRec[1]: ASK_RECORDING 1 29 0 0
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3505 (HandleTuning) TVRec[1]: HandleTuning Request: Program(NULL) channel() input() flags(NOREC,)
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3574 (TuningShutdowns) TVRec[1]: TuningShutdowns(Program(NULL) channel() input() flags(NOREC,))
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:2097 (TeardownSignalMonitor) TVRec[1]: TeardownSignalMonitor() -- begin
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/streamhandler.cpp:82 (RemoveListener) SH[1]: RemoveListener(0x7fc048157858) -- begin
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/streamhandler.cpp:94 (RemoveListener) SH[1]: RemoveListener(0x7fc048157858) -- locked
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satipstreamhandler.cpp:197 (run) SatIPSH[1]: RunTS(): shutdown
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satiprtsp.cpp:184 (Play) SatIPRTSP[1]: Play(pids) pids=none
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:394 (stopKeepAliveRequested) SatIPRTSP[1]: stopKeepAliveRequested() m_timer:4
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satipstreamhandler.cpp:210 (run) SatIPSH[1]: RunTS(): end
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/streamhandler.cpp:111 (RemoveListener) SH[1]: RemoveListener(0x7fc048157858) -- end
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/satipstreamhandler.cpp:75 (Return) SatIPSH[1]: Return stream handler for uuid:3eec0475-c365-44e7-bf7c-6d53b0daf8e4:DVBS2:1 (3 users)
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:2116 (TeardownSignalMonitor) TVRec[1]: TeardownSignalMonitor() -- end
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(SignalMonitorRunning,) -> RunMainLoop,EITScannerRunning,RingBufferReady, @ tv_rec.cpp:3595
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop,EITScannerRunning,RingBufferReady, @ tv_rec.cpp:3641
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3527 (HandleTuning) TVRec[1]: No recorder yet, calling TuningFrequency
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3663 (TuningFrequency) TVRec[1]: TuningFrequency
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: E TVRecEvent tv_rec.cpp:3736 (TuningFrequency) TVRec[1]: Failed to set channel to . Reverting to kState_None
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3505 (HandleTuning) TVRec[1]: HandleTuning Request: Program(NULL) channel() input() flags(KillRec,)
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3574 (TuningShutdowns) TVRec[1]: TuningShutdowns(Program(NULL) channel() input() flags(KillRec,))
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1623 (HandlePendingRecordings) TVRec[2]: ASK_RECORDING 2 28 0 0
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(EITScannerRunning,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:3581
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I Scheduler scheduler.cpp:2310 (HandleReschedule) Reschedule requested for MATCH 0 0 0 2021-02-13T21:00:00Z EITScanner
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:3641
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3505 (HandleTuning) TVRec[1]: HandleTuning Request: Program(NULL) channel() input() flags(NOREC,)
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3574 (TuningShutdowns) TVRec[1]: TuningShutdowns(Program(NULL) channel() input() flags(NOREC,))
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:3641
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3527 (HandleTuning) TVRec[1]: No recorder yet, calling TuningFrequency
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3663 (TuningFrequency) TVRec[1]: TuningFrequency
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: E TVRecEvent tv_rec.cpp:3736 (TuningFrequency) TVRec[1]: Failed to set channel to . Reverting to kState_None
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3505 (HandleTuning) TVRec[1]: HandleTuning Request: Program(NULL) channel() input() flags(KillRec,)
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3574 (TuningShutdowns) TVRec[1]: TuningShutdowns(Program(NULL) channel() input() flags(KillRec,))
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1623 (HandlePendingRecordings) TVRec[4]: ASK_RECORDING 4 29 0 0
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:3641
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1623 (HandlePendingRecordings) TVRec[5]: ASK_RECORDING 5 28 0 0
Feb 13 20:59:30 tv mythbackend: mythbackend[8076]: I Scheduler scheduler.cpp:2424 (HandleReschedule) Scheduled 74 items in 0.2 = 0.11 match + 0.02 check + 0.10 place
Feb 13 20:59:40 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:405 (timerEvent) SatIPRTSP[5]: Sending KeepAlive timer 6
Feb 13 20:59:44 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:405 (timerEvent) SatIPRTSP[6]: Sending KeepAlive timer 8
Feb 13 20:59:47 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:405 (timerEvent) SatIPRTSP[8]: Sending KeepAlive timer 10
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:402 (StartRecording) TVRec[1]: StartRecording("Line of Duty")
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:689 (SetRecordingStatus) TVRec[1]: SetRecordingStatus(Recording->Aborted) on line 408
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:471 (StartRecording) TVRec[1]: Checking input group recorders - begin
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:545 (StartRecording) TVRec[1]: Checking input group recorders - done
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:791 (StartedRecording) TVRec[1]: StartedRecording(65792_2021-02-13T21:00:00Z) fn(/media/library/TV/65792_20210213210000.ts)
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:4140 (LoadProfile) TVRec[1]: Using profile 'Default' to record
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(CancelNextRecording,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:590
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:689 (SetRecordingStatus) TVRec[1]: SetRecordingStatus(Aborted->Tuning) on line 593
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1058 (HandleStateChange) TVRec[1]: Changing from None to RecordingOnly
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:1297
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3505 (HandleTuning) TVRec[1]: HandleTuning Request: Program(ProgramInfo(65792_20210213210000.ts): channame(BBC ONE HD)#012             startts(Sat Feb 13 21:00:00 2021 GMT) endts(Sat Feb 13 22:00:00 2021 GMT)#012             recstartts(Sat Feb 13 21:00:00 2021 GMT) recendts(Sat Feb 13 22:00:00 2021 GMT)#012             title(Line of Duty)) channel() input() flags(Recording,)
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3574 (TuningShutdowns) TVRec[1]: TuningShutdowns(Program(ProgramInfo(65792_20210213210000.ts): channame(BBC ONE HD)#012             startts(Sat Feb 13 21:00:00 2021 GMT) endts(Sat Feb 13 22:00:00 2021 GMT)#012             recstartts(Sat Feb 13 21:00:00 2021 GMT) recendts(Sat Feb 13 22:00:00 2021 GMT)#012             title(Line of Duty)) channel(101) input(None) flags(Recording,))
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:3641
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3527 (HandleTuning) TVRec[1]: No recorder yet, calling TuningFrequency
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3663 (TuningFrequency) TVRec[1]: TuningFrequency
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent cardutil.cpp:2092 (GetConflictingInputs) CardUtil[1]: GetConflictingInputs(1) 4
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/satipstreamhandler.cpp:217 (Tune) SatIPSH[1]: Tune 10847000
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/satipstreamhandler.cpp:266 (Tune) SatIPSH[1]: Tune url:rtsp://192.168.0.44:554/?fe=2&freq=10847.00&pol=v&ro=0.20&msys=dvbs2&mtype=8psk&sr=23000&fec=34&plts=auto
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/satiprtsp.cpp:184 (Play) SatIPRTSP[1]: Play(pids) pids=none
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:388 (startKeepAliveRequested) SatIPRTSP[1]: startKeepAliveRequested(30000) m_timer:4
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3799 (TuningFrequency) TVRec[1]: Starting Signal Monitor
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:2040 (SetupSignalMonitor) TVRec[1]: SetupSignalMonitor(1, 0)
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/satipstreamhandler.cpp:53 (Get) SatIPSH[1]: Using existing stream handler for uuid:3eec0475-c365-44e7-bf7c-6d53b0daf8e4:DVBS2:1 (3 users)
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:2064 (SetupSignalMonitor) TVRec[1]: Signal monitor successfully created
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1860 (SetupDTVSignalMonitor) TVRec[1]: Setting up table monitoring.
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4140 (LoadProfile) TVRec[1]: Using profile 'Live TV' to record
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1935 (SetupDTVSignalMonitor) TVRec[1]: DVB service_id 6941 on net_id 2 tsid 2050
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1957 (SetupDTVSignalMonitor) TVRec[1]: Successfully set up DVB table monitoring.
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4425 (SetFlags) TVRec[1]: SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady, @ tv_rec.cpp:3826
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady, @ tv_rec.cpp:3827
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4425 (SetFlags) TVRec[1]: SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,RingBufferReady, @ tv_rec.cpp:3832
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,RingBufferReady, @ tv_rec.cpp:3893
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4425 (SetFlags) TVRec[1]: SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,RingBufferReady, @ tv_rec.cpp:3895
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4010 (TuningSignalCheck) TVRec[1]: TuningSignalCheck: Still waiting.  Will timeout @ 21:59:50.000
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler scheduler.cpp:2877 (HandleRecordingStatusChange) Tuning recording: "Line of Duty": channel 65792 on cardid [1], sourceid 1
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:402 (StartRecording) TVRec[2]: StartRecording("The Little Stranger")
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:689 (SetRecordingStatus) TVRec[2]: SetRecordingStatus(Unknown->Aborted) on line 408
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:471 (StartRecording) TVRec[2]: Checking input group recorders - begin
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:545 (StartRecording) TVRec[2]: Checking input group recorders - done
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:791 (StartedRecording) TVRec[2]: StartedRecording(65888_2021-02-13T21:00:00Z) fn(/media/library/TV/65888_20210213210000.ts)
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:4140 (LoadProfile) TVRec[2]: Using profile 'Default' to record
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:4434 (ClearFlags) TVRec[2]: ClearFlags(CancelNextRecording,) -> RunMainLoop, @ tv_rec.cpp:590
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler tv_rec.cpp:689 (SetRecordingStatus) TVRec[2]: SetRecordingStatus(Aborted->Tuning) on line 593
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1058 (HandleStateChange) TVRec[2]: Changing from None to RecordingOnly
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[2]: ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop, @ tv_rec.cpp:1297
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3505 (HandleTuning) TVRec[2]: HandleTuning Request: Program(ProgramInfo(65888_20210213210000.ts): channame(Channel 4 HD)#012             startts(Sat Feb 13 21:00:00 2021 GMT) endts(Sat Feb 13 23:15:00 2021 GMT)#012             recstartts(Sat Feb 13 21:00:00 2021 GMT) recendts(Sat Feb 13 23:15:00 2021 GMT)#012             title(The Little Stranger)) channel() input() flags(Recording,)
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent mythdbcon.cpp:419 (PurgeIdleConnections) New DB connection, total: 11
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3574 (TuningShutdowns) TVRec[2]: TuningShutdowns(Program(ProgramInfo(65888_20210213210000.ts): channame(Channel 4 HD)#012             startts(Sat Feb 13 21:00:00 2021 GMT) endts(Sat Feb 13 23:15:00 2021 GMT)#012             recstartts(Sat Feb 13 21:00:00 2021 GMT) recendts(Sat Feb 13 23:15:00 2021 GMT)#012             title(The Little Stranger)) channel(104) input(None) flags(Recording,))
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I SignalMonitor recorders/streamhandler.cpp:40 (AddListener) SH[1]: AddListener(0x7fc0481650d8) -- begin
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I SignalMonitor recorders/streamhandler.cpp:52 (AddListener) SH[1]: AddListener(0x7fc0481650d8) -- locked
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satipstreamhandler.cpp:157 (run) SatIPSH[1]: RunTS(): begin
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I SignalMonitor recorders/streamhandler.cpp:74 (AddListener) SH[1]: AddListener(0x7fc0481650d8) -- end
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satiprtsp.cpp:184 (Play) SatIPRTSP[1]: Play(pids) pids=0,1,16,17,20
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: C CoreContext programinfo.cpp:252 (ProgramInfo) ProgramInfo(): Failed to find recorded entry for 0.
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[2]: ClearFlags(PENDINGACTIONS,) -> RunMainLoop, @ tv_rec.cpp:3641
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3527 (HandleTuning) TVRec[2]: No recorder yet, calling TuningFrequency
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3663 (TuningFrequency) TVRec[2]: TuningFrequency
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent cardutil.cpp:2092 (GetConflictingInputs) CardUtil[2]: GetConflictingInputs(2) 5
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/satipstreamhandler.cpp:217 (Tune) SatIPSH[5]: Tune 11126500
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/satipstreamhandler.cpp:266 (Tune) SatIPSH[5]: Tune url:rtsp://192.168.0.44:554/?fe=3&freq=11126.50&pol=v&ro=0.35&msys=dvbs&mtype=qpsk&sr=22000&fec=56&plts=auto
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:394 (stopKeepAliveRequested) SatIPRTSP[5]: stopKeepAliveRequested() m_timer:6
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/satiprtsp.cpp:184 (Play) SatIPRTSP[5]: Play(pids) pids=none
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:388 (startKeepAliveRequested) SatIPRTSP[5]: startKeepAliveRequested(30000) m_timer:6
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3799 (TuningFrequency) TVRec[2]: Starting Signal Monitor
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:2040 (SetupSignalMonitor) TVRec[2]: SetupSignalMonitor(1, 0)
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/satipstreamhandler.cpp:53 (Get) SatIPSH[2]: Using existing stream handler for uuid:3eec0475-c365-44e7-bf7c-6d53b0daf8e4:DVBS2:2 (3 users)
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:2064 (SetupSignalMonitor) TVRec[2]: Signal monitor successfully created
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1860 (SetupDTVSignalMonitor) TVRec[2]: Setting up table monitoring.
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4140 (LoadProfile) TVRec[2]: Using profile 'Live TV' to record
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1935 (SetupDTVSignalMonitor) TVRec[2]: DVB service_id 21200 on net_id 2 tsid 2068
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:1957 (SetupDTVSignalMonitor) TVRec[2]: Successfully set up DVB table monitoring.
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4425 (SetFlags) TVRec[2]: SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning, @ tv_rec.cpp:3826
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[2]: ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning, @ tv_rec.cpp:3827
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4425 (SetFlags) TVRec[2]: SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning, @ tv_rec.cpp:3832
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[2]: ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning, @ tv_rec.cpp:3893
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4425 (SetFlags) TVRec[2]: SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning, @ tv_rec.cpp:3895
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4010 (TuningSignalCheck) TVRec[2]: TuningSignalCheck: Still waiting.  Will timeout @ 23:14:50.000
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I Scheduler scheduler.cpp:2877 (HandleRecordingStatusChange) Tuning recording: "The Little Stranger": channel 65888 on cardid [2], sourceid 1
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: N Scheduler scheduler.cpp:3233 (HandleIdleShutdown) Blocking shutdown because of an active encoder
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: N Scheduler scheduler.cpp:3244 (HandleIdleShutdown) Blocking shutdown because of delay request from external application
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:575 (timerEvent) SatIPRTSP[1]: RTP Sequence number mismatch 50700!=18320, discarded 2 RTP packets
Feb 13 21:00:00 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satiprtsp.cpp:184 (Play) SatIPRTSP[1]: Play(pids) pids=0,1,16,17,20,192,260
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satiprtsp.cpp:184 (Play) SatIPRTSP[1]: Play(pids) pids=0,1,16,17,20,192,260,2321,2322,2329,3840,3841,3842,3843,3844,3846,3847,3849,3851,5400,5401,5402,5403,5404
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: E CoreContext mpeg/pespacket.cpp:93 (AddTSPacket) AddTSPacket[1]: Out of sync!!! Need to wait for next payloadStart PID: 0x11, continuity counter: 5 (expected 4)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:575 (timerEvent) SatIPRTSP[2]: RTP Sequence number mismatch 24461!=23211, discarded 1 RTP packets
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:3921 (TuningSignalCheck) TVRec[1]: TuningSignalCheck: Good signal
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:689 (SetRecordingStatus) TVRec[1]: SetRecordingStatus(Tuning->Recording) on line 4019
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:2097 (TeardownSignalMonitor) TVRec[1]: TeardownSignalMonitor() -- begin
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext scheduler.cpp:707 (UpdateRecStatus) Updating status for "Line of Duty" on cardid [1] (Tuning => Recording)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satiprtsp.cpp:184 (Play) SatIPRTSP[1]: Play(pids) pids=0,1,16,17,18,20,192,260,2321,2322,2329,3840,3841,3842,3843,3844,3846,3847,3849,3851,5400,5401,5402,5403,5404
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/streamhandler.cpp:82 (RemoveListener) SH[1]: RemoveListener(0x7fc0481650d8) -- begin
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/streamhandler.cpp:94 (RemoveListener) SH[1]: RemoveListener(0x7fc0481650d8) -- locked
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satipstreamhandler.cpp:197 (run) SatIPSH[1]: RunTS(): shutdown
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satiprtsp.cpp:184 (Play) SatIPRTSP[1]: Play(pids) pids=none
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:394 (stopKeepAliveRequested) SatIPRTSP[1]: stopKeepAliveRequested() m_timer:4
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satipstreamhandler.cpp:210 (run) SatIPSH[1]: RunTS(): end
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/streamhandler.cpp:111 (RemoveListener) SH[1]: RemoveListener(0x7fc0481650d8) -- end
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/satipstreamhandler.cpp:75 (Return) SatIPSH[1]: Return stream handler for uuid:3eec0475-c365-44e7-bf7c-6d53b0daf8e4:DVBS2:1 (3 users)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:2116 (TeardownSignalMonitor) TVRec[1]: TeardownSignalMonitor() -- end
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,RingBufferReady, @ tv_rec.cpp:4045
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,RingBufferReady, @ tv_rec.cpp:4047
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4172 (TuningNewRecorder) TVRec[1]: Starting Recorder
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4140 (LoadProfile) TVRec[1]: Using profile 'Default' to record
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4210 (TuningNewRecorder) TVRec[1]: rec->GetPathname(): '/media/library/TV/65792_20210213210000.ts'
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4243 (TuningNewRecorder) TVRec[1]: TuningNewRecorder - CreateRecorder()
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/dtvrecorder.cpp:140 (ResetForNewFile) DTVRec[1]: ResetForNewFile(void)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/recorderbase.cpp:81 (SetRingBuffer) RecBase[1](uuid:3eec0475-c365-44e7-bf7c-6d53b0daf8e4:DVBS2:1): SetRingBuffer(0x7fc010037200) '/media/library/TV/65792_20210213210000.ts'
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/recorderbase.cpp:92 (SetRecording) RecBase[1](uuid:3eec0475-c365-44e7-bf7c-6d53b0daf8e4:DVBS2:1): SetRecording(0x7fc010025e30) title(Line of Duty)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent mpeg/mpegstreamdata.cpp:73 (SetDesiredProgram) MPEGStream[1](0x7fc0481650d8): SetDesiredProgram(6941)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/dtvrecorder.cpp:1281 (HandlePAT) DTVRec[1]: SetPAT(6941 on pid 0x104)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/dtvrecorder.cpp:1301 (HandlePMT) DTVRec[1]: SetPMT(6941, valid)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent recorders/dtvrecorder.cpp:1307 (HandlePMT) DTVRec[1]: SetPMT(6941)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I RecThread recorders/satiprecorder.cpp:74 (run) SatIPRec[1]: run -- begin
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I RecThread recorders/dtvrecorder.cpp:140 (ResetForNewFile) DTVRec[1]: ResetForNewFile(void)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I RecThread recorders/satipstreamhandler.cpp:53 (Get) SatIPSH[1]: Using existing stream handler for uuid:3eec0475-c365-44e7-bf7c-6d53b0daf8e4:DVBS2:1 (3 users)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I RecThread recorders/satiprecorder.cpp:44 (Open) SatIPRec[1]: SatIP opened successfully
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4425 (SetFlags) TVRec[1]: SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady, @ tv_rec.cpp:4314
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:4434 (ClearFlags) TVRec[1]: ClearFlags(NeedToStartRecorder,) -> RunMainLoop,RecorderRunning,RingBufferReady, @ tv_rec.cpp:4316
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I RecThread recorders/streamhandler.cpp:40 (AddListener) SH[1]: AddListener(0x7fc0481650d8) -- begin
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I RecThread recorders/streamhandler.cpp:52 (AddListener) SH[1]: AddListener(0x7fc0481650d8) -- locked
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satipstreamhandler.cpp:157 (run) SatIPSH[1]: RunTS(): begin
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I RecThread recorders/streamhandler.cpp:74 (AddListener) SH[1]: AddListener(0x7fc0481650d8) -- end
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:388 (startKeepAliveRequested) SatIPRTSP[1]: startKeepAliveRequested(30000) m_timer:4
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satiprtsp.cpp:184 (Play) SatIPRTSP[1]: Play(pids) pids=0,1,16,17,18,20,192,256,257,258,259,260,262,263,264,265,266,2321,2322,2329,3840,3841,3842,3843,3844,3846,3847,3849,3851,5400,5401,5402,5403,5404
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I SatIPStreamHandler recorders/satiprtsp.cpp:189 (Play) SatIPRTSP[1]: Receive full TS, number of PIDs:34 is more than 32
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:575 (timerEvent) SatIPRTSP[1]: RTP Sequence number mismatch 34707!=51044, discarded 95 RTP packets
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: E CoreContext mpeg/pespacket.cpp:93 (AddTSPacket) AddTSPacket[1]: Out of sync!!! Need to wait for next payloadStart PID: 0x104, continuity counter: 12 (expected 8)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1301 (HandlePMT) DTVRec[1]: SetPMT(6963, valid)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1301 (HandlePMT) DTVRec[1]: SetPMT(6943, valid)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1301 (HandlePMT) DTVRec[1]: SetPMT(6945, valid)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1301 (HandlePMT) DTVRec[1]: SetPMT(6912, valid)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1301 (HandlePMT) DTVRec[1]: SetPMT(6961, valid)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1301 (HandlePMT) DTVRec[1]: SetPMT(6940, valid)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1301 (HandlePMT) DTVRec[1]: SetPMT(6960, valid)
Feb 13 21:00:01 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1301 (HandlePMT) DTVRec[1]: SetPMT(6972, valid)
Feb 13 21:00:02 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1301 (HandlePMT) DTVRec[1]: SetPMT(6952, valid)
Feb 13 21:00:02 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1018 (FindH2645Keyframes) DTVRec[1]: FindH2645Keyframes: timescale: 50, tick: 1, framerate: 25000
Feb 13 21:00:02 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1631 (ProcessAVTSPacket) DTVRec[1]: PID 0x1518 Found Payload Start
Feb 13 21:00:02 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1631 (ProcessAVTSPacket) DTVRec[1]: PID 0x1519 Found Payload Start
Feb 13 21:00:02 tv mythbackend: mythbackend[8076]: I CoreContext recorders/dtvrecorder.cpp:1631 (ProcessAVTSPacket) DTVRec[1]: PID 0x151a Found Payload Start
Feb 13 21:00:03 tv mythbackend: mythbackend[8076]: E TVRecEvent tv_rec.cpp:3968 (TuningSignalCheck) TVRec[2]: TuningSignalCheck: Hit pre-fail timeout
Feb 13 21:00:04 tv mythbackend: mythbackend[8076]: W TVRecEvent tv_rec.cpp:3996 (TuningSignalCheck) TVRec[2]: TuningSignalCheck: taking more than 3000 ms to get a lock. marking this recording as 'Failing'.
Feb 13 21:00:04 tv mythbackend: mythbackend[8076]: W TVRecEvent tv_rec.cpp:4001 (TuningSignalCheck) TVRec[2]: See 'Tuning timeout' in mythtv-setup for this input
Feb 13 21:00:04 tv mythbackend: mythbackend[8076]: I TVRecEvent tv_rec.cpp:689 (SetRecordingStatus) TVRec[2]: SetRecordingStatus(Tuning->Failing) on line 4019
Feb 13 21:00:04 tv mythbackend: mythbackend[8076]: I CoreContext scheduler.cpp:707 (UpdateRecStatus) Updating status for "The Little Stranger" on cardid [2] (Tuning => Failing)
Feb 13 21:00:04 tv mythbackend: mythbackend[8076]: I Scheduler scheduler.cpp:2310 (HandleReschedule) Reschedule requested for CHECK -14 7582 0 UpdateRecStatus2 | The Little Stranger |  | Post-war gothic drama starring Ruth Wilson and Domhnall Gleeson. When a doctor is called to a mansion in the village where he grew up, it's very different from what he imagined... | MV181627698
Feb 13 21:00:04 tv mythbackend: mythbackend[8076]: I Scheduler scheduler.cpp:2424 (HandleReschedule) Scheduled 74 items in 0.1 = 0.00 match + 0.00 check + 0.10 place

Last edited 5 months ago by jksj461 (previous) (diff)

Changed 5 months ago by jksj461

Attachment:	debug.txt added

Failed Recording noting short timeout

comment:57 Changed 5 months ago by Klaas de Waal

Done some testing, 3 times two recordings starting at the same time, and they are all good.

Your failing recordings seem to be on TVRec[2], so the second tuner. Maybe this tuner currently does not work at all anymore. It could just be that everything is OK again after a reboot of the Digibit. Can you please try that?

Not really relevant to your recording problem, but your log format is rather different from mine. This is from your log:

Feb 13 20:59:40 tv mythbackend: mythbackend[8076]: I CoreContext recorders/satiprtsp.cpp:405 (timerEvent) SatIPRTSP[5]: Sending KeepAlive timer 6

This is a similar message from my log:

2021-02-14 14:07:01.713803 I [380058/380058] CoreContext recorders/satiprtsp.cpp:405 (timerEvent) - SatIPRTSP[11]: Sending KeepAlive timer 2

And this also with the latest, c64556b924.

comment:58 Changed 5 months ago by David Hampton

That looks like the difference between logging to syslog/systemd and logging to a logfile.

comment:59 Changed 5 months ago by jksj461

Zero byte recording:- Seems to have been a one off, I have been testing and cannot repeat the issue, so many thanks.

comment:60 Changed 5 months ago by fe31nz

I have been recording SAT>IP with MythTV for several years now by manually putting URLs into the database using IPTV (FREEBOX) tuners as per https://www.mythtv.org/wiki/SAT2IP_players_as_capture_cards.

It is good to see real SAT>IP support arriving for v32, and I thought I had better test it to make sure it was going to work for me. I have set up a new PC using the old motherboard from my mother's MythTV box, put Xubuntu 20.04 on it and installed v32 from the PPA.

For my current production system I am using minisatip on the same box as my main MythTV system, which has a TBS6909 8 tuner DVB-S2 card and a TBS6209 8 tuner DVB-T2 card. Mythbackend directly uses 5 of the TBS6209 DVB-T2 tuners for the 5 DVB-T muxes available here in New Zealand, and my MHEG5 EPG gathering uses one more of the DVB-T2 tuners, leaving two DVB-T2 tuners for minisatip. One of the TBS6909 DVB-S2 tuners is used for OpenTV format EPG gathering and the other 7 DVB-S2 tuners are used by minisatip. Minisatip uses my Sky NZ satellite card to decrypt my pay TV channels via Oscam. My mother's MythTV box also connects to minisatip to record Sky NZ channels.

On the new test PC, I created two sources, one for DVB-T and one for DVB-S2. I created two SAT>IP tuners, one for each source, and tried channel scanning. Scanning on the DVB-T tuner worked fine and I was able to record from the channels it put in the database. However, when I try to scan using the DVB-S2 tuner, I immediately get a popup error message "Error parsing parameters". I used Wireshark to check for traffic to minisatip, and the error was occurring before any packets were sent. I tried a number of different combinations of scan settings to see if that would help, but I got the same error each time. Then I deleted all sources and tuners and started again with only one source for DVB-S2 and one DVB-S2 SAT>IP tuner. But I got exactly the same error message.

MythTV Version : v32.0~master.202102151820.e787645fd9~ubuntu20.04.1 MythTV Branch : master Network Protocol : 91 Library API : 32.20200101-1 QT Version : 5.12.8 Options compiled in:

linux profile use_hidesyms using_alsa using_oss using_pulse using_pulseoutput using_backend using_bindings_perl using_bindings_python using_bindings_php using_dvb using_firewire using_frontend using_hdhomerun using_satip using_vbox using_ceton using_hdpvr using_ivtv using_joystick_menu using_libcec using_libcrypto using_gnutls using_libdns_sd using_libfftw3 using_libxml2 using_lirc using_mheg using_opengl using_egl using_qtwebkit using_qtscript using_qtdbus using_taglib using_v4l2 using_v4l2prime using_x11 using_libbluray_external using_profiletype using_systemd_notify using_systemd_journal using_drm using_bindings_perl using_bindings_python using_bindings_php using_freetype2 using_mythtranscode using_opengl using_egl using_drm using_vaapi using_nvdec using_vdpau using_ffmpeg_threads using_mheg using_libass using_libxml2 using_libmp3lame

Klaas: If it is any use for your testing, I should be able to make my minisatip available for Internet connections - but that would require that connections came from static IP addresses that I could whitelist in my router. Leaving completely open ports to minisatip would not be a good idea. I have a fibre connection with 1 Gbit/s downstream and 500 Mbit/s upstream and my ISP's international bandwidth is good.

comment:61 Changed 5 months ago by Klaas de Waal

I might just take you up on that offer when things get difficult...

But first check the setup for the channelscan. The error message indicates that the tuning parameters are not filled in. Configuring his is the same for Sat>IP and for conventional satellite tuners, but it is different from how it used to be a few MythTV versions ago and it is not as user-friendly as it could be.

When you are in the Channel Scan page you have to select Scan Type. Select Full Scan (Tuned). This requires that you know the tuning parameters for the first multiplex. Press right arrow to get to the window to fill the tuning parameters, as described here: https://www.mythtv.org/wiki/Channel_Scanning#Full_Scan_.28Tuned.29 Press the left arrow to get back to the Channel Scan page. Then one choice down to the Scan button and do the scan. This should now work.

If you are happy with the scan then put the frequency of the initial transport in the Video Source. This frequency, and the tuning parameters of that transport, will then be the default the next time you do a Full Scan (Tuned).

If this fails then please post the command sequence/configuration/version for minisatip so that I can try to reproduce the problem.

comment:62 Changed 3 months ago by Klaas de Waal

Sat>IP is not stable with today's master. It is a bit difficult to test as it can run OK for one or two days before failing. This could be a bug that was always there or it could be caused by another update in the last few months. To be investigated.

Last edited 3 months ago by Klaas de Waal (previous) (diff)

comment:63 Changed 3 months ago by Klaas de Waal

Sat>IP fails repeatable with the following sequence:

recording in progress, starting at 05:00 and scheduled to end at 06:00
nightly database backup starts at 05:30
the recording ends as "Bad quality" with a gap starting at 05:32 and ending at 06:00
the continuity_error_count is 0 so the recording from 05:00 to 05:32 is perfect

After the recording has failed the RTP communication path is completely dead. The RTCP communication seems to be still working. A restart of the backend is enough to make it working again; the Sat>IP box does not need to be reset or rebooted. Current hypothesis is:

the database backup causes the Sat>IP to fail
possible causes can be CPU starvation, disk I/O starvation or database locking
the actual problem is likely to be in the RTP part.

As a workaround I recommend to avoid scheduling recordings together with database backups or even any other kind of backups or heavy CPU load.

comment:64 Changed 3 months ago by fe31nz

In my MythTV 0.31-fixes system where I record from SAT>IP using IPTV URLs, I have a number of recordings (7 this year so far) that were done at the same time that I have my daily anacron jobs running (which include my MythTV database check and backup jobs). They seem to have recorded without any problems. This method of recording uses URLs like this in iptv_channel:

rtsp://satip.jsw.gen.nz:554/?src=1&freq=12546&msys=dvbs2&plts=off&fec=23&pol=h&ro=0.35&sr=22500&mtype=8psk&pids=0,311,1011,1111,1911

and appears to use the RTP/RTSP code that was originally create for Ceton tuners. So if the new SAT>IP code is using the same RTP/RTSP code, then it should also be able to record through the database checking and backups. My database is extremely large - the last backup .tar.gz file is 2,994,561,822 bytes. The checking and backup of it is very intensive work and only happens in a reasonable time due to my running it on a very fast NVMe SSD. Howvever, to prevent problems at some time in the past I altered my /etc/cron.daily/mythtv-database file so that it runs mythconverg_backup.pl at lower priority (nice -n 2), and I run a modified version mythconverg_backup.pl that puts its temporary file (before compression) on the same NVMe SSD instead of on the ultimate destination drive for the backup file (a network drive on my Windows box).

If you want to try them, I have put my /etc/cron.daily/mythtv-database and /usr/local/bin/mythconverg_backup_jsw.pl files on my web server:

http://www.jsw.gen.nz/mythtv/mythtv-database

http://www.jsw.gen.nz/mythtv/mythconverg_backup_jsw.pl

comment:65 Changed 3 months ago by Klaas de Waal

My backup script, dating from 2011, makes a backup with mythconverg_backup.pl but it also makes a second backup with mysqldump on the entire mythconverg database. The backup with mysqldump on the entire database causes the problems as this blocks the Housekeeper task. The Housekeeper tasks then blocks the complete mythbackend.

What happens is this:

Sat>IP recording in progress
The backup with mysqldump of the entire database starts
Sat>IP recording continues
The Housekeeper starts (it does this every minute)
After the last log message line of the Housekeeper mythbackend is frozen
Sat>IP recording stops
The backup with mysqldump finishes
mythbackend unfreezes
Sat>IP fails with "sendMessage read: RTSP/1.0 454 Session Not Found" for the keepAlive message.

The Sat>IP box has a session timeout of 60 seconds; therefore a keepAlive message is sent every 30 seconds. The keepAlive messages are not sent when mythbackend is frozen and thus the session times out when the frozen period is long enough. The Sat>IP box is then idle while mythbackend thinks it is still recording.

This problem showed up when I started to use the Sat>IP on my living room system which has a much larger database than my development system and hence the backup takes much longer.

The first solution, removing the mysqldump of the complete database and using only the mythconverg_backup.pl, is now under test.

A better solution is to use the backup scripts of fe31nz: do first a backup to a SSD and then later do the compression and the copying. To be tested.

The Sat>IP code can be improved so that it can recover from the "Session Not Found". If this happens the current recording should be terminated and it should be possible to start a new recording.

Also the Housekeeper task can be investigated. After starting the mysqldump backup the recording continues, but only when the Housekeeper task runs mythbackend completely freezes. Even when the Houskeeper task is blocked it should not need to block recordings.

comment:66 Changed 2 months ago by Klaas de Waal

With the backup scripts from fe31nz my system works nearly perfect. However, the underlying problem is still there and it is about what runs in which thread, as already indicated in comment:29.

Sat>IP is started at system start in the CoreContext? thread at the moment where all capture cards are opened and tuned just to see if they are present. The Sat>IP streams are never closed.

The CoreContext? thread is where all non-recording activities of mythbackend, such as the housekeeping tasks, are done. This explains why the Housekeeper tasks do influence the Sat->IP recordings and this also explains why such a large UDP input buffer, 8Mbyte, is needed to avoid packet loss.

The recording is started in the TVRecEvent thread. In this thread we have to read the control stream to check if the tuner is in lock. This does not work if the UDP socket is created in the TVRecEvent thread; it looks like there is no event handler in this thread but it can also be a bug in my test code.

At least reading the media stream data from the UDP socket has to be moved in the SatIPStreamHandler::run thread but maybe it is easier to recreate also reading the control stream in this thread once the tuner is locked.

Note: See TracTickets for help on using tickets.

Download in other formats: