DVR stopped for upgrade, never restarted

dkrach · October 18, 2017, 4:27am

I’m using my own dyndns domain name, and recently started accessing with https, I’m assuming this is why there are so many TLS errors in the log. Do you see that as a potential problem?

tmm1 · October 18, 2017, 6:13am

The TLS errors are not a big deal, but I’d recommend using my.channelsdvr.net for HTTPs access so it’s using valid cert. When you use a different domain, a self-signed certificate is used which causes various warnings and prompts depending on the browser or HTTP client.

I’m pretty sure the issue is fixed in the latest DVR update, but can’t be 100% positive. So I’d appreciate if you keep an eye on it, and if you notice the issue again try to grab a debug snapshot without remote desktop.

dkrach · November 5, 2017, 4:35am

It’s been almost 3 weeks, but the DVR disabled itself again tonight while waiting for an upgrade which never completed. I grabbed the debug output this time, hopefully it’s more use to figure this out.

goroutine 12159 [running]:
main.StartHTTPServer.func34(0xc420292580)
	/Users/fancybox/source/channels-server/http.go:757 +0xaa
github.com/gin-gonic/gin.(*Context).Next(0xc420292580)
	/Users/fancybox/source/channels-server/.go/src/github.com/gin-gonic/gin/context.go:104 +0x43
main.authMiddleware(0xc420292580)
	/Users/fancybox/source/channels-server/http.go:185 +0x2e7
github.com/gin-gonic/gin.(*Context).Next(0xc420292580)
	/Users/fancybox/source/channels-server/.go/src/github.com/gin-gonic/gin/context.go:104 +0x43
github.com/gin-gonic/gin.RecoveryWithWriter.func1(0xc420292580)
	/Users/fancybox/source/channels-server/.go/src/github.com/gin-gonic/gin/recovery.go:45 +0x5a
github.com/gin-gonic/gin.(*Context).Next(0xc420292580)
	/Users/fancybox/source/channels-server/.go/src/github.com/gin-gonic/gin/context.go:104 +0x43
github.com/gin-gonic/contrib/sessions.Sessions.func1(0xc420292580)
	/Users/fancybox/source/channels-server/.go/src/github.com/gin-gonic/contrib/sessions/sessions.go:65 +0x1c0
github.com/gin-gonic/gin.(*Context).Next(0xc420292580)
	/Users/fancybox/source/channels-server/.go/src/github.com/gin-gonic/gin/context.go:104 +0x43
github.com/gin-contrib/gzip.Gzip.func2(0xc420292580)
	/Users/fancybox/source/channels-server/.go/src/github.com/gin-contrib/gzip/gzip.go:47 +0x216
github.com/gin-gonic/gin.(*Context).Next(0xc420292580)
	/Users/fancybox/source/channels-server/.go/src/github.com/gin-gonic/gin/context.go:104 +0x43
main.StartHTTPServer.func1(0xc420292580)
	/Users/fancybox/source/channels-server/http.go:249 +0xbf
github.com/gin-gonic/gin.(*Context).Next(0xc420292580)
	/Users/fancybox/source/channels-server/.go/src/github.com/gin-gonic/gin/context.go:104 +0x43
github.com/gin-gonic/gin.(*Engine).handleHTTPRequest(0xc42008d200, 0xc420292580)
	/Users/fancybox/source/channels-server/.go/src/github.com/gin-gonic/gin/gin.go:332 +0x5b4
github.com/gin-gonic/gin.(*Engine).ServeHTTP(0xc42008d200, 0x4d82400, 0xc42306e000, 0xc42039e200)
	/Users/fancybox/source/channels-server/.go/src/github.com/gin-gonic/gin/gin.go:296 +0x16b
net/http.serverHandler.ServeHTTP(0xc42007d6c0, 0x4d82400, 0xc42306e000, 0xc42039e200)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/server.go:2619 +0xb4
net/http.(*conn).serve(0xc42044c320, 0x4d83340, 0xc42216c400)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/server.go:1801 +0x71d
created by net/http.(*Server).Serve
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/server.go:2720 +0x288

goroutine 1 [syscall, 4569 minutes, locked to thread]:
_/Users/fancybox/source/channels-server/menubar._Cfunc_StartApp()
	_/Users/fancybox/source/channels-server/menubar/_obj/_cgo_gotypes.go:70 +0x41
_/Users/fancybox/source/channels-server/menubar.Start(0xc420182700, 0x7, 0x8)
	/Users/fancybox/source/channels-server/menubar/menubar.go:34 +0xc4
main.StartMenu()
	/Users/fancybox/source/channels-server/menu_darwin.go:69 +0x2e1
main.main()
	/Users/fancybox/source/channels-server/main.go:182 +0x3e1

goroutine 18 [select, 735 minutes]:
github.com/blevesearch/bleve/index.AnalysisWorker(0xc42023a000, 0xc42023a060)
	/Users/fancybox/source/channels-server/.go/src/github.com/blevesearch/bleve/index/analysis.go:75 +0x127
created by github.com/blevesearch/bleve/index.NewAnalysisQueue
	/Users/fancybox/source/channels-server/.go/src/github.com/blevesearch/bleve/index/analysis.go:67 +0xcd

goroutine 19 [select, 735 minutes]:
github.com/blevesearch/bleve/index.AnalysisWorker(0xc42023a000, 0xc42023a060)
	/Users/fancybox/source/channels-server/.go/src/github.com/blevesearch/bleve/index/analysis.go:75 +0x127
created by github.com/blevesearch/bleve/index.NewAnalysisQueue
	/Users/fancybox/source/channels-server/.go/src/github.com/blevesearch/bleve/index/analysis.go:67 +0xcd

goroutine 20 [select, 735 minutes]:
github.com/blevesearch/bleve/index.AnalysisWorker(0xc42023a000, 0xc42023a060)
	/Users/fancybox/source/channels-server/.go/src/github.com/blevesearch/bleve/index/analysis.go:75 +0x127
created by github.com/blevesearch/bleve/index.NewAnalysisQueue
	/Users/fancybox/source/channels-server/.go/src/github.com/blevesearch/bleve/index/analysis.go:67 +0xcd

goroutine 21 [select, 735 minutes]:
github.com/blevesearch/bleve/index.AnalysisWorker(0xc42023a000, 0xc42023a060)
	/Users/fancybox/source/channels-server/.go/src/github.com/blevesearch/bleve/index/analysis.go:75 +0x127
created by github.com/blevesearch/bleve/index.NewAnalysisQueue
	/Users/fancybox/source/channels-server/.go/src/github.com/blevesearch/bleve/index/analysis.go:67 +0xcd

goroutine 22 [syscall, 4569 minutes]:
os/signal.signal_recv(0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/sigqueue.go:131 +0xa7
os/signal.loop()
	/usr/local/Cellar/go/1.9.2/libexec/src/os/signal/signal_unix.go:22 +0x22
created by os/signal.init.0
	/usr/local/Cellar/go/1.9.2/libexec/src/os/signal/signal_unix.go:28 +0x41

goroutine 43 [select, 69 minutes]:
main.StartAuth.func1(0xc42017cf70)
	/Users/fancybox/source/channels-server/main.go:96 +0x178
created by main.StartAuth
	/Users/fancybox/source/channels-server/main.go:89 +0x124

goroutine 30 [IO wait]:
internal/poll.runtime_pollWait(0x56a4af0, 0x72, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc420104018, 0x72, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitRead(0xc420104018, 0xc420463000, 0x800, 0x800)
	/usr/local/Cellar/go/1.9.2/libexec/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).ReadFrom(0xc420104000, 0xc420463000, 0x800, 0x800, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/internal/poll/fd_unix.go:170 +0x19a
net.(*netFD).readFrom(0xc420104000, 0xc420463000, 0x800, 0x800, 0x0, 0x0, 0x0, 0x1, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/fd_unix.go:208 +0x5e
net.(*UDPConn).readFrom(0xc4206d6018, 0xc420463000, 0x800, 0x800, 0xd2, 0xc42319e240, 0x0, 0xc42024c9d0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/udpsock_posix.go:47 +0x6a
net.(*UDPConn).ReadFrom(0xc4206d6018, 0xc420463000, 0x800, 0x800, 0x0, 0x1000, 0xc42319e240, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/udpsock.go:118 +0x72
github.com/huin/goupnp/httpu.(*HTTPUClient).Do(0xc42027ea60, 0xc42039e000, 0xb8c63f00, 0x4, 0x0, 0x0, 0x0, 0x0, 0x0)
	/Users/fancybox/source/channels-server/.go/src/github.com/huin/goupnp/httpu/httpu.go:107 +0x6b3
github.com/tmm1/goupnp/ssdp.SSDPRawSearch(0xc42027ea60, 0x49640d1, 0x8, 0x3, 0x4, 0x404d546, 0xc42002d180, 0xc42023d200, 0xc4202d8f58, 0x402f7be)
	/Users/fancybox/source/channels-server/.go/src/github.com/tmm1/goupnp/ssdp/ssdp.go:53 +0x5b6
_/Users/fancybox/source/channels-server/roku.Discover(0x0, 0x0, 0x0, 0x0, 0x0)
	/Users/fancybox/source/channels-server/roku/device.go:36 +0xec
main.StartRoku.func1()
	/Users/fancybox/source/channels-server/roku.go:14 +0x3a
created by main.StartRoku
	/Users/fancybox/source/channels-server/roku.go:10 +0x35

goroutine 29 [sleep, 7 minutes]:
time.Sleep(0x68c61714000)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/time.go:65 +0x130
main.StartHDHR.func1()
	/Users/fancybox/source/channels-server/main.go:52 +0x54
created by main.StartHDHR
	/Users/fancybox/source/channels-server/main.go:44 +0xc2

goroutine 51 [select, 4569 minutes, locked to thread]:
runtime.gopark(0x49a1008, 0x0, 0x4960b15, 0x6, 0x18, 0x1)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/proc.go:287 +0x12c
runtime.selectgo(0xc4204c9f50, 0xc4205b4060)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/select.go:395 +0x1149
runtime.ensureSigM.func1()
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/signal_unix.go:511 +0x1fe
runtime.goexit()
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/asm_amd64.s:2337 +0x1

goroutine 44 [chan receive, 1 minutes]:
github.com/soheilhy/cmux.muxListener.Accept(...)
	/Users/fancybox/source/channels-server/.go/src/github.com/soheilhy/cmux/cmux.go:228
github.com/soheilhy/cmux.(*muxListener).Accept(0xc4200da320, 0x4036dfb, 0xc42003dec8, 0x42ae918, 0x405a7e0)
	<autogenerated>:1 +0x65
crypto/tls.(*listener).Accept(0xc4200da340, 0x49a09b8, 0xc420419680, 0x4d83400, 0xc4201c22a0)
	/usr/local/Cellar/go/1.9.2/libexec/src/crypto/tls/tls.go:52 +0x37
net/http.(*Server).Serve(0xc42007d6c0, 0x4d81a80, 0xc4200da340, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/server.go:2695 +0x1b2
created by main.StartHTTPServer
	/Users/fancybox/source/channels-server/http.go:3243 +0x6207

goroutine 45 [chan receive]:
github.com/soheilhy/cmux.muxListener.Accept(...)
	/Users/fancybox/source/channels-server/.go/src/github.com/soheilhy/cmux/cmux.go:228
github.com/soheilhy/cmux.(*muxListener).Accept(0xc4200da360, 0x49a09b8, 0xc42044c320, 0x4d83400, 0xc4201c22d0)
	<autogenerated>:1 +0x65
net/http.(*Server).Serve(0xc42007d6c0, 0x4d827c0, 0xc4200da360, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/server.go:2695 +0x1b2
created by main.StartHTTPServer
	/Users/fancybox/source/channels-server/http.go:3247 +0x5f42

goroutine 46 [IO wait]:
internal/poll.runtime_pollWait(0x56a4d30, 0x72, 0xffffffffffffffff)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc420104418, 0x72, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitRead(0xc420104418, 0xffffffffffffff00, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Accept(0xc420104400, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/internal/poll/fd_unix.go:335 +0x1e2
net.(*netFD).accept(0xc420104400, 0xc4206d6028, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc42000f0f0, 0x465e07a, 0x405a7e0, 0xc420246f60)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/tcpsock_posix.go:136 +0x2e
net.(*TCPListener).Accept(0xc42000f0f0, 0x499e8d8, 0xc4201b8cd0, 0x4d88c80, 0xc4206d6028)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/tcpsock.go:247 +0x49
github.com/soheilhy/cmux.(*cMux).Serve(0xc4201b8cd0, 0x0, 0x0)
	/Users/fancybox/source/channels-server/.go/src/github.com/soheilhy/cmux/cmux.go:161 +0x95
created by main.StartHTTPServer
	/Users/fancybox/source/channels-server/http.go:3249 +0x5f6e

goroutine 47 [chan receive]:
main.liveStreamTicker()
	/Users/fancybox/source/channels-server/streams.go:143 +0xe9
created by main.StartHTTPServer
	/Users/fancybox/source/channels-server/http.go:3250 +0x5f86

goroutine 48 [chan receive]:
main.fileStreamTicker()
	/Users/fancybox/source/channels-server/streams.go:170 +0xe9
created by main.StartHTTPServer
	/Users/fancybox/source/channels-server/http.go:3251 +0x5f9e

goroutine 85 [syscall, 129 minutes, locked to thread]:
_/Users/fancybox/source/channels-server/menubar._Cfunc_StopApp()
	_/Users/fancybox/source/channels-server/menubar/_obj/_cgo_gotypes.go:82 +0x41
_/Users/fancybox/source/channels-server/menubar.Stop()
	/Users/fancybox/source/channels-server/menubar/menubar.go:38 +0x20
main.StopMenu()
	/Users/fancybox/source/channels-server/menu_darwin.go:73 +0x20
main.performRestart(0x0)
	/Users/fancybox/source/channels-server/updater.go:225 +0x14c
main.StartUpdater.func1()
	/Users/fancybox/source/channels-server/updater.go:57 +0x1f2
created by main.StartUpdater
	/Users/fancybox/source/channels-server/updater.go:42 +0x3c

goroutine 86 [chan receive, 4569 minutes]:
main.handleSignals()
	/Users/fancybox/source/channels-server/main.go:193 +0x77
created by main.main
	/Users/fancybox/source/channels-server/main.go:181 +0x3dc

goroutine 12160 [IO wait]:
internal/poll.runtime_pollWait(0x56a4bb0, 0x72, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc420104298, 0x72, 0xffffffffffffff00, 0x4d7e640, 0x4d789f0)
	/usr/local/Cellar/go/1.9.2/libexec/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitRead(0xc420104298, 0xc42319e300, 0x1, 0x1)
	/usr/local/Cellar/go/1.9.2/libexec/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc420104280, 0xc42319e341, 0x1, 0x1, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/internal/poll/fd_unix.go:126 +0x18a
net.(*netFD).Read(0xc420104280, 0xc42319e341, 0x1, 0x1, 0x2, 0xc42009e6f0, 0xc4201c8390)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/fd_unix.go:202 +0x52
net.(*conn).Read(0xc4206d6028, 0xc42319e341, 0x1, 0x1, 0x0, 0x0, 0x0)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/net.go:176 +0x6d
github.com/soheilhy/cmux.(*bufferedReader).Read(0xc42009e6f0, 0xc42319e341, 0x1, 0x1, 0x5, 0x13, 0x2)
	/Users/fancybox/source/channels-server/.go/src/github.com/soheilhy/cmux/buffer.go:53 +0x144
github.com/soheilhy/cmux.(*MuxConn).Read(0xc42009e6e0, 0xc42319e341, 0x1, 0x1, 0x2, 0xc420056180, 0xc4202d8fd0)
	/Users/fancybox/source/channels-server/.go/src/github.com/soheilhy/cmux/cmux.go:259 +0x4f
net/http.(*connReader).backgroundRead(0xc42319e330)
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/server.go:660 +0x62
created by net/http.(*connReader).startBackgroundRead
	/usr/local/Cellar/go/1.9.2/libexec/src/net/http/server.go:656 +0xd8

tmm1 · November 5, 2017, 4:55am

Thanks for keeping an eye out for it, and grabbing that debug info! It looks like a rare deadlock. I made a fix so hopefully it doesn’t happen after the next update.

If you do notice it again, I have an idea for a more brute-force fix that will definitely fix it once and for all.

gsulshski · November 5, 2017, 11:37am

I noticed that I have similar symptoms today and other findings in the last few days.

for the dvr upgrade 2017.11.01.2252, I got the waiting to upgrade to 2017.11.01.2252 but after 2 days it never upgraded. I had to reboot my mac mini for other reasons, and the upgrade occurred.

However, it wouldn’t start up (enable dvr) without I think some manual intervention after the reboot. I would check and uncheck Bonjour and after a few tries the DVR would be enabled
Today, I noticed that the DVR was not enabled

I saw that at midnight the DVR was stopped for the upgrade but It wasn’t applied.

I restarted the DVR manually since the DVR wasn’t started and it is in the waiting for an upgrade cycle.

gsulshski · November 5, 2017, 11:44am

2017/11/04 21:02:04 [SYS] Shutting down for upgrade from v2017.11.01.2252 to v2017.11.03.0006
2017/11/04 21:02:04 [DVR] Recording engine stopped.
2017/11/05 05:09:23 [DVR] Recording engine started in /Volumes/MacIntosh HD 2/DVR
2017/11/05 05:09:23 [DVR] Waiting 2h50m36.729662s until next job 1509890400-3 Meet the Press

gsulshski · November 5, 2017, 11:46am

Also, I have to turn off port forwarding manually and turn it back on to get remote access working

gsulshski · November 5, 2017, 11:57am

I emailed to the support email address my debug stack log in case that had some value.