Close source device, then record?

Channels DVR Server Troubleshooting
#1

Channels DVR is confused. Both of these recordings show interrupted. It closes the source connection, then starts recording. Huh?

2024/02/07 20:00:00.064568 [DVR] Starting job 1707364800-777 Nature on ch=[706]
2024/02/07 20:00:00.097816 [TNR] Sharing existing connection to 1323AADB/0 for ch706 KVIEDT (clients=1, len=0)
2024/02/07 20:00:00.107484 [TNR] Closed connection to 1323AADB/0 for ch706 KVIEDT
2024/02/07 20:00:00.177726 [DVR] Recording for job 1707364800-777 from 1323AADB ch706 into "TV/Nature/Nature S42E06 Flyways 2024-02-07-2000.mpg" for 59m59.902318208s
2024/02/07 20:00:01.234940 [IDX] Generating video index for job 1707364800-777
2024/02/07 20:00:01.621643 [SNR] Signal statistics for "TV/Nature/Nature S42E06 Flyways 2024-02-07-2000.mpg": ss=91%-92% snq=100% seq=100% bps=4314841,2836544-4475904 pps=369,243-383
2024/02/07 20:00:01.671930 [SNR] Buffer statistics for "TV/Nature/Nature S42E06 Flyways 2024-02-07-2000.mpg": buf=0% drop=0%
2024/02/07 20:00:01.672798 [DVR] Job 1707364800-777 Nature ended prematurely: 59m58.327203858s
2024/02/07 20:00:01.861415 [DVR] Starting job 1707364800-777 Nature on ch=[706]
2024/02/07 20:00:02.410599 [TNR] Opened connection to 1323AADB/0 for ch706 KVIEDT
2024/02/07 20:00:02.410783 [DVR] Recording for job 1707364800-777 from 1323AADB ch706 into "TV/Nature/Nature S42E06 Flyways 2024-02-07-2000.mpg" for 59m58.138455755s

2024/02/07 22:00:00.004119 [DVR] Starting job 1707372000-784 Secrets of the Dead on ch=[706]
2024/02/07 22:00:00.137936 [TNR] Closed connection to 1323AADB/0 for ch706 KVIEDT
2024/02/07 22:00:00.176573 [TNR] Sharing existing connection to 1323AADB/0 for ch706 KVIEDT (clients=1, len=0)
2024/02/07 22:00:00.273177 [DVR] Recording for job 1707372000-784 from 1323AADB ch706 into "TV/Secrets of the Dead/Secrets of the Dead S16E02 2016-11-02 Graveyard of the Giant Be 2024-02-07-2200.mpg" for 59m59.955290667s
2024/02/07 22:00:01.072264 [IDX] Generating video index for job 1707372000-784
2024/02/07 22:00:01.341709 [SNR] Signal statistics for "TV/Secrets of the Dead/Secrets of the Dead S16E02 2016-11-02 Graveyard of the Giant Be 2024-02-07-2200.mpg": ss=91%-92% snq=100% seq=100% bps=4316871,3257664-4475904 pps=369,279-384
2024/02/07 22:00:01.460500 [SNR] Buffer statistics for "TV/Secrets of the Dead/Secrets of the Dead S16E02 2016-11-02 Graveyard of the Giant Be 2024-02-07-2200.mpg": buf=0% drop=0%
2024/02/07 22:00:01.461686 [DVR] Job 1707372000-784 Secrets of the Dead ended prematurely: 59m58.538316884s
2024/02/07 22:00:01.576428 [DVR] Starting job 1707372000-784 Secrets of the Dead on ch=[706]
2024/02/07 22:00:02.258227 [TNR] Opened connection to 1323AADB/0 for ch706 KVIEDT
2024/02/07 22:00:02.258453 [DVR] Recording for job 1707372000-784 from 1323AADB ch706 into "TV/Secrets of the Dead/Secrets of the Dead S16E02 2016-11-02 Graveyard of the Giant Be 2024-02-07-2200.mpg" for 59m58.423459505s

Logs have been submitted as f244663e-f93a-4d5e-a759-086a358f7eaa

#2

It opened a shared connection then the original one closed. Normal for logs to be in different orders when threads are running in parallel.

#3

They're both marked interrupted.

Screenshot 2024-02-08 at 17-21-30 Channels Manage Recordings
Screenshot 2024-02-08 at 17-21-30 Channels Manage Recordings924×218 38.1 KB

HDHR log (8hrs ahead) - That's not tuner sharing

20240208-02:59:58 Tuner: tuner0 tuning 706 KVIEDT (auto:129MHz-452)
20240208-02:59:59 Tuner: tuner0 streaming http to 192.168.1.4:40098
20240208-03:59:59 Tuner: tuner0 http stream ended (remote closed)

20240208-04:00:01 Tuner: tuner0 tuning 706 KVIEDT (auto:129MHz-452)
20240208-04:00:01 Tuner: tuner0 streaming http to 192.168.1.4:43016
20240208-04:59:59 Tuner: tuner0 http stream ended (remote closed)

20240208-04:59:59 Tuner: tuner0 tuning 706 KVIEDT (auto:129MHz-452)
20240208-04:59:59 Tuner: tuner0 streaming http to 192.168.1.4:43078
20240208-05:59:59 Tuner: tuner0 http stream ended (remote closed)

20240208-06:00:01 Tuner: tuner0 tuning 706 KVIEDT (auto:129MHz-452)
20240208-06:00:01 Tuner: tuner0 streaming http to 192.168.1.4:43174
20240208-06:59:58 Tuner: tuner0 http stream ended (remote closed)
#4

Interesting. Do you operate with 0 padding? We could be running into a race condition of the system being very precise and with a lack of overlap, having the close and open happen almost simultaneously.

#5

Yes, for the PBS channel passes, no pre or post padding.

The recordings were not actually interrupted because they didn't start until the source device was re-opened. They were technically "delayed due to the bug".

Just thought I should raise awareness since this behavior is now in the new stable version.

#6

Nothing has changed in this code in a year, so I'm suspecting this is an old latent bug that crops up from time-to-time that most people haven't noticed. Thanks for flagging this... it is very strange.

1 Like
#7

Then definitely strange since my passes record these shows each week from PBS and I never saw this before. Will post if it happens again, but the recordings are fine, other than the Interrupted tag.

1 Like