Check the main dvr log on http://127.0.0.1:8089/log?n=20000 and scroll back to the time of the recording
Here you go for the last one it happened to
2019/11/07 21:00:00 [DVR] Starting job 1573178400-1 The Good Place on ch=[41.1 2.1]
2019/11/07 21:00:00 [TNR] Opened connection to 103B2BDF for ch41.1 CIII
2019/11/07 21:00:00 [DVR] Recording for job 1573178400-1 from 103B2BDF ch41.1 into "TV\The Good Place\The Good Place S04E07 Help Is Other People 2019-11-07-2100.mpg" for 29m59.9870621s
2019/11/07 21:00:00 [IDX] Generating video index for job 1573178400-1
2019/11/07 21:29:57 [TNR] Closed connection to 103B2BDF for ch41.1 CIII
2019/11/07 21:29:57 [DVR] Job 1573178400-1 The Good Place ended prematurely: 2.4620733s
2019/11/07 21:29:57 [DVR] Starting job 1573178400-1 The Good Place on ch=[41.1 2.1]
2019/11/07 21:29:57 [TNR] Opened connection to 103B2BDF for ch41.1 CIII
2019/11/07 21:29:57 [DVR] Recording for job 1573178400-1 from 103B2BDF ch41.1 into "TV\The Good Place\The Good Place S04E07 Help Is Other People 2019-11-07-2100.mpg" for 2.4492577s
2019/11/07 21:30:00 [TNR] Closed connection to 103B2BDF for ch41.1 CIII
2019/11/07 21:30:00 [DVR] Finished job 1573178400-1 The Good Place
2019/11/07 21:30:00 [DVR] Processing file-43: TV\The Good Place\The Good Place S04E07 Help Is Other People 2019-11-07-2100.mpg
2019/11/07 21:30:01 [DVR] Running commercial detection on file 43 (TV\The Good Place\The Good Place S04E07 Help Is Other People 2019-11-07-2100.mpg)
2019/11/07 21:39:05 [DVR] Commercial detection finished with 8 markers.
2019/11/07 21:39:06 [IDX] Generating video index for file-43: The Good Place S04E07 Help Is Other People 2019-11-07-2100.mpg
2019/11/07 21:40:00 [IDX] Finished video index generation for file-43 in 53s
Interesting. Thanks.
Can you search for other "ended prematurely" and post them?
yup doing that right now. will post as i find them. should have another 2 or 3
unfortunately the log only goes back to Nov 6th and the other interrupted ones I have was before that. sorry. If I get another I'll post
1 Like
oh wait that's only through the UI - looking at the full file here's another:
2019/09/19 20:00:00 [DVR] Starting job 1568937600-2 Battle of the Blades on ch=[5.1]
2019/09/19 20:00:00 [DVR] Waiting 2h29m59.9856825s until next job 1568946600-6 Seinfeld
2019/09/19 20:00:00 [TNR] Opened connection to 103B2BDF for ch5.1 CBLT-DT
2019/09/19 20:00:00 [DVR] Recording for job 1568937600-2 from 103B2BDF ch5.1 into "TV\Battle of the Blades\Battle of the Blades S05E01 2019-09-19 2019-09-19-2000.mpg" for 1h59m59.9856825s
2019/09/19 20:00:00 [DVR] Refreshing metadata for Battle of the Blades (7815369)
2019/09/19 20:00:00 [IDX] Generating video index for job 1568937600-2
2019/09/19 20:06:45 [TNR] Cancelling stream 103B2BDF ch5.1 after 6s read timeout
2019/09/19 20:06:45 [TNR] Closed connection to 103B2BDF for ch5.1 CBLT-DT
2019/09/19 20:06:45 [TNR] Closed connection to 103B2BDF for ch5.1 CBLT-DT
2019/09/19 20:06:45 [DVR] Job 1568937600-2 Battle of the Blades ended prematurely: 1h53m14.4861871s
2019/09/19 20:06:45 [DVR] Starting job 1568937600-2 Battle of the Blades on ch=[5.1]
2019/09/19 20:06:45 [DVR] Waiting 2h23m14.481193s until next job 1568946600-6 Seinfeld
2019/09/19 20:06:45 [TNR] Opened connection to 103B2BDF for ch5.1 CBLT-DT
2019/09/19 20:06:45 [DVR] Recording for job 1568937600-2 from 103B2BDF ch5.1 into "TV\Battle of the Blades\Battle of the Blades S05E01 2019-09-19 2019-09-19-2000.mpg" for 1h53m14.481193s
2019/09/19 20:47:27 [DVR] Rule 'Stumptown' (7) found 2 new airings
2019/09/19 20:47:27 [DVR] queued recording job for EP032294370001 @ Wed Sep 25 10:00:00PM (1569463200-7)
2019/09/19 20:47:27 [DVR] queued recording job for EP032294370002 @ Wed Oct 2 10:00:00PM (1570068000-7)
2019/09/19 20:47:27 [DVR] Waiting 1h42m32.6857359s until next job 1568946600-6 Seinfeld
e[31m2019/09/19 20:49:03 [Recovery] 2019/09/19 - 20:49:03 panic recovered:
POST /dvr/rules/priority HTTP/1.1
Host: 192.168.0.24:8089
Accept: application/json
Accept-Encoding: gzip, deflate
Accept-Language: en-ca
Connection: keep-alive
Content-Length: 31
Content-Type: application/x-www-form-urlencoded
User-Agent: Channels/8.16.2355 CFNetwork/978.0.7 Darwin/18.7.0
runtime error: invalid memory address or nil pointer dereference
/home/vagrant/go/src/runtime/panic.go:82 (0x445bf5)
/home/vagrant/go/src/runtime/signal_windows.go:233 (0x445a90)
/home/vagrant/channels-server-win64/http_dvr_rule.go:36 (0x113da7d)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/channels-server-win64/http.go:210 (0x1107a62)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/channels-server-win64/http.go:190 (0x11068c3)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/recovery.go:48 (0xa44750)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/channels-server-win64/http.go:265 (0x1121722)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/gopath/pkg/mod/github.com/gin-contrib/[email protected]/sessions.go:65 (0xff8c46)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/gopath/pkg/mod/github.com/gin-contrib/[email protected]/gzip.go:47 (0xff16cc)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/channels-server-win64/http.go:245 (0x11214e8)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:361 (0xa3ba8d)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:326 (0xa3b2aa)
/home/vagrant/go/src/net/http/server.go:2774 (0x6ffcae)
/home/vagrant/go/src/net/http/server.go:1878 (0x6fb797)
/home/vagrant/go/src/runtime/asm_amd64.s:1337 (0x45fcb0)
e[0m
e[31m2019/09/19 20:50:38 [Recovery] 2019/09/19 - 20:50:38 panic recovered:
POST /dvr/rules/priority HTTP/1.1
Host: 192.168.0.24:8089
Accept: application/json
Accept-Encoding: gzip, deflate
Accept-Language: en-ca
Connection: keep-alive
Content-Length: 31
Content-Type: application/x-www-form-urlencoded
User-Agent: Channels/8.16.2355 CFNetwork/978.0.7 Darwin/18.7.0
runtime error: invalid memory address or nil pointer dereference
/home/vagrant/go/src/runtime/panic.go:82 (0x445bf5)
/home/vagrant/go/src/runtime/signal_windows.go:233 (0x445a90)
/home/vagrant/channels-server-win64/http_dvr_rule.go:36 (0x113da7d)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/channels-server-win64/http.go:210 (0x1107a62)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/channels-server-win64/http.go:190 (0x11068c3)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/recovery.go:48 (0xa44750)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/channels-server-win64/http.go:265 (0x1121722)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/gopath/pkg/mod/github.com/gin-contrib/[email protected]/sessions.go:65 (0xff8c46)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/gopath/pkg/mod/github.com/gin-contrib/[email protected]/gzip.go:47 (0xff16cc)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/channels-server-win64/http.go:245 (0x11214e8)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/context.go:108 (0xa32f19)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:361 (0xa3ba8d)
/home/vagrant/gopath/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:326 (0xa3b2aa)
/home/vagrant/go/src/net/http/server.go:2774 (0x6ffcae)
/home/vagrant/go/src/net/http/server.go:1878 (0x6fb797)
/home/vagrant/go/src/runtime/asm_amd64.s:1337 (0x45fcb0)
e[0m
2019/09/19 22:00:00 [TNR] Closed connection to 103B2BDF for ch5.1 CBLT-DT
2019/09/19 22:00:00 [DVR] Finished job 1568937600-2 Battle of the Blades
2019/09/19 22:00:00 [DVR] Waiting 29m59.9412392s until next job 1568946600-6 Seinfeld
2019/09/19 22:00:00 [DVR] Processing file-5: TV\Battle of the Blades\Battle of the Blades S05E01 2019-09-19 2019-09-19-2000.mpg
2019/09/19 22:00:01 [DVR] Running commercial detection on file 5 (TV\Battle of the Blades\Battle of the Blades S05E01 2019-09-19 2019-09-19-2000.mpg)
here's another
2019/10/17 22:00:00 [DVR] Starting job 1571364000-14 Evil on ch=[41.1 4.1]
2019/10/17 22:00:00 [TNR] Opened connection to 103B2BDF for ch41.1 CIII
2019/10/17 22:00:00 [DVR] Recording for job 1571364000-14 from 103B2BDF ch41.1 into "TV\Evil\Evil S01E04 2019-10-17 Rose390 2019-10-17-2200.mpg" for 59m59.995717s
2019/10/17 22:00:00 [DVR] Refreshing metadata for Evil (16935389)
2019/10/17 22:00:00 [IDX] Generating video index for job 1571364000-14
2019/10/17 22:59:57 [TNR] Closed connection to 103B2BDF for ch41.1 CIII
2019/10/17 22:59:57 [DVR] Job 1571364000-14 Evil ended prematurely: 2.1649829s
2019/10/17 22:59:57 [DVR] Starting job 1571364000-14 Evil on ch=[41.1 4.1]
2019/10/17 22:59:57 [TNR] Opened connection to 103B2BDF for ch41.1 CIII
2019/10/17 22:59:57 [DVR] Recording for job 1571364000-14 from 103B2BDF ch41.1 into "TV\Evil\Evil S01E04 2019-10-17 Rose390 2019-10-17-2200.mpg" for 2.1609835s
2019/10/17 23:00:00 [TNR] Closed connection to 103B2BDF for ch41.1 CIII
2019/10/17 23:00:00 [DVR] Finished job 1571364000-14 Evil
2019/10/17 23:00:00 [DVR] Processing file-30: TV\Evil\Evil S01E04 2019-10-17 Rose390 2019-10-17-2200.mpg
2019/10/17 23:00:01 [DVR] Running commercial detection on file 30 (TV\Evil\Evil S01E04 2019-10-17 Rose390 2019-10-17-2200.mpg)
2019/10/17 23:17:37 [DVR] Commercial detection finished with 12 markers.
2019/10/17 23:17:37 [IDX] Generating video index for file-30: Evil S01E04 2019-10-17 Rose390 2019-10-17-2200.mpg
2019/10/17 23:19:25 [IDX] Finished video index generation for file-30 in 107s
This one was some sort of network or antenna issue. No data was received in 6s so the dvr reconnected. This happened right away so only a few seconds of the recording was lost.
This is like the earlier one where the recording was almost over. Seems like there might be a bug in this area where the dvr is stopping the recording just before the actual end time.
2 Likes
I’ve started seeing these as well. Here is an example from the logs:
2020/01/06 23:30:00 [DVR] Starting job 1578371400-68 Perry Mason on ch=[36.3]
2020/01/06 23:30:00 [DVR] Waiting 18h59m59.995172545s until next job 1578439800-57 NBC Nightly News With Lester Holt
2020/01/06 23:30:00 [TNR] Opened connection to 107188DD/0 for ch36.3 MeTV
2020/01/06 23:30:00 [DVR] Recording for job 1578371400-68 from 107188DD ch36.3 into "TV/Perry Mason/Perry Mason S03E13 1960-01-23 The Case of the Wayward Wife 2020-01-06-2330.mpg" for 1h0m29.995116314s
2020/01/06 23:30:00 [IDX] Generating video index for job 1578371400-68
2020/01/06 23:55:22 [NAT] Successfully mapped port 8089 using natpmp
2020/01/07 00:30:27 [TNR] Closed connection to 107188DD/0 for ch36.3 MeTV
2020/01/07 00:30:28 [SNR] Statistics for "TV/Perry Mason/Perry Mason S03E13 1960-01-23 The Case of the Wayward Wife 2020-01-06-2330.mpg": ss=100% snq=91%,72%-100% seq=100% bps=3263680,1054304-3523872 pps=310,104-335
2020/01/07 00:30:28 [DVR] Job 1578371400-68 Perry Mason ended prematurely: 1.73136953s
2020/01/07 00:30:28 [DVR] Starting job 1578371400-68 Perry Mason on ch=[36.3]
2020/01/07 00:30:28 [DVR] Waiting 17h59m31.61443858s until next job 1578439800-57 NBC Nightly News With Lester Holt
2020/01/07 00:30:28 [TNR] Opened connection to 107188DD/0 for ch36.3 MeTV
2020/01/07 00:30:28 [DVR] Recording for job 1578371400-68 from 107188DD ch36.3 into "TV/Perry Mason/Perry Mason S03E13 1960-01-23 The Case of the Wayward Wife 2020-01-06-2330.mpg" for 1.614382818s
2020/01/07 00:30:30 [TNR] Closed connection to 107188DD/0 for ch36.3 MeTV
2020/01/07 00:30:30 [DVR] Finished job 1578371400-68 Perry Mason
2020/01/07 00:30:31 [DVR] Waiting 17h59m28.880291225s until next job 1578439800-57 NBC Nightly News With Lester Holt
2020/01/07 00:30:31 [DVR] Processing file-2686: TV/Perry Mason/Perry Mason S03E13 1960-01-23 The Case of the Wayward Wife 2020-01-06-2330.mpg
2020/01/07 00:30:31 [DVR] Running commercial detection on file 2686 (TV/Perry Mason/Perry Mason S03E13 1960-01-23 The Case of the Wayward Wife 2020-01-06-2330.mpg)
2020/01/07 00:34:46 [DVR] Commercial detection finished with 14 markers.
2020/01/07 00:34:47 [IDX] Generating video index for file-2686: Perry Mason S03E13 1960-01-23 The Case of the Wayward Wife 2020-01-06-2330.mpg
The recording itself looked normal. The HDHomeruns and the Qnap NAS where the DVR runs are all on the same switch and vlan. What other info can I collect to help troubleshoot this ?