Odd issue with recording halting early and out of order log entries

Channels DVR Server Troubleshooting
#1

For the past several days, a scheduled recording (same daily one) has halted early (under a second before end of show, so not a major issue), and looking in logs I see the same out-of-order log entry related to closing of this channel (entry 2022/05/06 16:00:00.020465 about the middle of the below):

2022/05/06 15:00:00.001715 [DVR] Starting job 1651874400-21 The Ellen DeGeneres Show on ch=[6000]
2022/05/06 15:00:00.001860 [DVR] Waiting 12h59m59.998148946s until next job 1651921200-1 Barefoot Contessa
2022/05/06 15:00:02.088310 [TVE] stream timestamps: nbc: start_at=2022-05-06T14:59:00-07:00 current_at=2022-05-06T14:59:36-07:00 end_at=2022-05-06T14:59:48-07:00
2022/05/06 15:00:02.088523 [TNR] Opened connection to TVE-Hulu for ch6000 KING
2022/05/06 15:00:02.089050 [DVR] Recording for job 1651874400-21 from TVE-Hulu ch6000 into "TV/The Ellen DeGeneres Show/The Ellen DeGeneres Show S19E162 Tiffany Haddish Cynthia Erivo 2022-05-06-1500.mpg" for 59m59.998035733s
2022/05/06 15:00:02.550868 [IDX] Generating video index for job 1651874400-21
2022/05/06 15:26:58.473184 [DVR] Waiting 12h33m1.526830758s until next job 1651921200-1 Barefoot Contessa
2022/05/06 16:00:00.020465 [TNR] Closed connection to TVE-Hulu for ch6000 KING
2022/05/06 15:59:58.126425 [MTS] Statistics for "TV/The Ellen DeGeneres Show/The Ellen DeGeneres Show S19E162 Tiffany Haddish Cynthia Erivo 2022-05-06-1500.mpg": skipped=0 unhandled_packets=0 discontinuity_detected=0 transport_errors=0 invalid_pts=0 invalid_dts=0 saw_pcr=true saw_pmt=true highest_pts=3613.688056
2022/05/06 15:59:58.152231 [DVR] Job 1651874400-21 The Ellen DeGeneres Show ended prematurely: 1.8477902s
2022/05/06 15:59:58.271850 [DVR] Starting job 1651874400-21 The Ellen DeGeneres Show on ch=[6000]
2022/05/06 15:59:58.272012 [DVR] Waiting 12h0m1.727997463s until next job 1651921200-1 Barefoot Contessa
2022/05/06 15:59:59.802353 [TVE] stream timestamps: nbc: start_at=2022-05-06T15:59:01-07:00 current_at=2022-05-06T15:59:37-07:00 end_at=2022-05-06T15:59:49-07:00
2022/05/06 15:59:59.802531 [TNR] Opened connection to TVE-Hulu for ch6000 KING
2022/05/06 15:59:59.802633 [DVR] Recording for job 1651874400-21 from TVE-Hulu ch6000 into "TV/The Ellen DeGeneres Show/The Ellen DeGeneres Show S19E162 Tiffany Haddish Cynthia Erivo 2022-05-06-1500.mpg" for 1.72792205s
2022/05/06 16:00:00.001363 [TNR] Closed connection to TVE-Hulu for ch6000 KING
2022/05/06 16:00:00.086888 [MTS] Statistics for "TV/The Ellen DeGeneres Show/The Ellen DeGeneres Show S19E162 Tiffany Haddish Cynthia Erivo 2022-05-06-1500.mpg": skipped=0 unhandled_packets=0 discontinuity_detected=0 transport_errors=0 invalid_pts=0 invalid_dts=0 saw_pcr=false saw_pmt=false highest_pts=0.000000
2022/05/06 16:00:00.087116 [DVR] Finished job 1651874400-21 The Ellen DeGeneres Show
2022/05/06 16:00:00.239252 [DVR] Processing file-7436: TV/The Ellen DeGeneres Show/The Ellen DeGeneres Show S19E162 Tiffany Haddish Cynthia Erivo 2022-05-06-1500.mpg

Any ideas or things to check?

Running DVR version 2022.04.28.1311

Thanks.

#2

I'm thinking it might be the time sync (NTP) on the qnap NAS. So I am testing a change to the update schedule to see if this continues.

2 Likes
#3

For anyone seeing similar out-of-order log entries, check your NTP update schedule.

Today's recording of the same show did not have this issue.

While my schedule (QNAP) does not provide details of exactly when it runs (it only offer # times per day type setting), I adjusted it to a new schedule (from every 6 hours, to daily) and I am fairly certain this is what fixed it.

1 Like