Sporadic Web Sever Crash

[UncleJohnsBand]

About a month ago I started seeing sporadic Cassini web server crashes occur. Below is the log info from the gbpvrrecording service.

GBPVR Recording Service Log:

Code:

2008-07-14 00:13:52.285 VERBOSE [14] Hour is currently 0. Conversions will happen between 1:00 and 6:00 2008-07-14 00:44:52.261 VERBOSE [14] Hour is currently 0. Conversions will happen between 1:00 and 6:00 2008-07-14 01:15:52.253 VERBOSE [14] Hour is currently 1. Conversions will happen between 1:00 and 6:00 2008-07-14 01:46:52.229 VERBOSE [14] Hour is currently 1. Conversions will happen between 1:00 and 6:00 2008-07-14 02:17:02.191 VERBOSE [14] Hour is currently 2. Conversions will happen between 1:00 and 6:00 2008-07-14 02:48:02.167 VERBOSE [14] Hour is currently 2. Conversions will happen between 1:00 and 6:00 2008-07-14 03:18:07.144 VERBOSE [14] Hour is currently 3. Conversions will happen between 1:00 and 6:00 2008-07-14 03:48:22.120 VERBOSE [14] Hour is currently 3. Conversions will happen between 1:00 and 6:00 2008-07-14 04:18:27.660 VERBOSE [14] Hour is currently 4. Conversions will happen between 1:00 and 6:00 2008-07-14 04:48:28.093 VERBOSE [14] Hour is currently 4. Conversions will happen between 1:00 and 6:00 2008-07-14 04:56:22.612 ERROR [11] FATAL UNHANDLED EXCEPTION:: System.Net.Sockets.SocketException: Only one usage of each socket address (protocol/network address/port) is normally permitted Server stack trace: at System.Net.Sockets.Socket.DoBind(EndPoint endPointSnapshot, SocketAddress socketAddress) at System.Net.Sockets.Socket.Bind(EndPoint localEP) at Cassini.x1b6b12494b043e38.x2dcc0ca8fed1d43b() at System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs) at System.Runtime.Remoting.Messaging.StackBuilderSink.PrivateProcessMessage(RuntimeMethodHandle md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs) at System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(IMessage msg, Int32 methodPtr, Boolean fExecuteInContext) Exception rethrown at [0]: at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg) at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type) at Cassini.x1b6b12494b043e38.x2dcc0ca8fed1d43b() at Cassini.xcdc6d50076d34ea4.x1eebd27da31f16e1(Object xf236ab116fb26f27) at System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(Object state) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(_ThreadPoolWaitCallback tpWaitCallBack) at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(Object state)

System Event Log Entry:

Code:

Event Type: Error Event Source: Service Control Manager Event Category: None Event ID: 7034 Date: 7/14/2008 Time: 04:57:16 AM User: N/A Computer: DEN Description: The GB-PVR Recording Service service terminated unexpectedly. It has done this 2 time(s). For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.

App Event Log Entry #1:

Code:

Event Type: Error Event Source: ASP.NET 2.0.50727.0 Event Category: None Event ID: 1334 Date: 7/14/2008 Time: 04:56:22 AM User: N/A Computer: DEN Description: An unhandled exception occurred and the process was terminated. Application ID: GBPVRRecordingService.exe Process ID: 3992 Exception: System.Net.Sockets.SocketException Message: Only one usage of each socket address (protocol/network address/port) is normally permitted StackTrace: Server stack trace: at System.Net.Sockets.Socket.DoBind(EndPoint endPointSnapshot, SocketAddress socketAddress) at System.Net.Sockets.Socket.Bind(EndPoint localEP) at Cassini.x1b6b12494b043e38.x2dcc0ca8fed1d43b() at System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs) at System.Runtime.Remoting.Messaging.StackBuilderSink.PrivateProcessMessage(RuntimeMethodHandle md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs) at System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(IMessage msg, Int32 methodPtr, Boolean fExecuteInContext) Exception rethrown at [0]: at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg) at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type) at Cassini.x1b6b12494b043e38.x2dcc0ca8fed1d43b() at Cassini.xcdc6d50076d34ea4.x1eebd27da31f16e1(Object xf236ab116fb26f27) at System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(Object state) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(_ThreadPoolWaitCallback tpWaitCallBack) at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(Object state) For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp.

App Event Log Entry #2:

Code:

Event Type: Error Event Source: .NET Runtime 2.0 Error Reporting Event Category: None Event ID: 5000 Date: 7/14/2008 Time: 04:56:31 AM User: N/A Computer: DEN Description: EventType clr20r3, P1 gbpvrrecordingservice.exe, P2 1.0.3069.9824, P3 3a, P4 mscorlib, P5 2.0.0.0, P6 471ebc5b, P7 416b, P8 27, P9 system.net.sockets.socket, P10 NIL. For more information, see Help and Support Center at http://go.microsoft.com/fwlink/events.asp. Data: 0000: 63 00 6c 00 72 00 32 00 c.l.r.2. 0008: 30 00 72 00 33 00 2c 00 0.r.3.,. 0010: 20 00 67 00 62 00 70 00 .g.b.p. 0018: 76 00 72 00 72 00 65 00 v.r.r.e. 0020: 63 00 6f 00 72 00 64 00 c.o.r.d. 0028: 69 00 6e 00 67 00 73 00 i.n.g.s. 0030: 65 00 72 00 76 00 69 00 e.r.v.i. 0038: 63 00 65 00 2e 00 65 00 c.e...e. 0040: 78 00 65 00 2c 00 20 00 x.e.,. . 0048: 31 00 2e 00 30 00 2e 00 1...0... 0050: 33 00 30 00 36 00 39 00 3.0.6.9. 0058: 2e 00 39 00 38 00 32 00 ..9.8.2. 0060: 34 00 2c 00 20 00 33 00 4.,. .3. 0068: 61 00 2c 00 20 00 6d 00 a.,. .m. 0070: 73 00 63 00 6f 00 72 00 s.c.o.r. 0078: 6c 00 69 00 62 00 2c 00 l.i.b.,. 0080: 20 00 32 00 2e 00 30 00 .2...0. 0088: 2e 00 30 00 2e 00 30 00 ..0...0. 0090: 2c 00 20 00 34 00 37 00 ,. .4.7. 0098: 31 00 65 00 62 00 63 00 1.e.b.c. 00a0: 35 00 62 00 2c 00 20 00 5.b.,. . 00a8: 34 00 31 00 36 00 62 00 4.1.6.b. 00b0: 2c 00 20 00 32 00 37 00 ,. .2.7. 00b8: 2c 00 20 00 73 00 79 00 ,. .s.y. 00c0: 73 00 74 00 65 00 6d 00 s.t.e.m. 00c8: 2e 00 6e 00 65 00 74 00 ..n.e.t. 00d0: 2e 00 73 00 6f 00 63 00 ..s.o.c. 00d8: 6b 00 65 00 74 00 73 00 k.e.t.s. 00e0: 2e 00 73 00 6f 00 63 00 ..s.o.c. 00e8: 6b 00 65 00 74 00 20 00 k.e.t. . 00f0: 4e 00 49 00 4c 00 0d 00 N.I.L... 00f8: 0a 00 ..

[sub]

Do you happen to know if that was first time the web server was used since the recording service was last started? or had it been used, but then left idle for several hours, and this was the first use after the idle period? or something else entirely?

[UncleJohnsBand]

Do you happen to know if that was first time the web server was used since the recording service was last started? or had it been used, but then left idle for several hours, and this was the first use after the idle period? or something else entirely?

Something else entirely.....hadn't been used for several (>6) hours. The crash is all by itself....nothing is accessing it at this time.

Every time it crashes like this it appears to be early in the a.m. and I am not accessing anything. There is not a set time or frequency for it happening.....I had it happen a couple days in a row....then 3 days a-ok.....then two days in a row....that type of uncrackable pattern.

It is very strange.

[sub]

I'm not quite sure how I'll track this one down.

Is that "early in the a.m" the same time as anything else? For example, EPG update?

[UncleJohnsBand]

I'm not quite sure how I'll track this one down.

Is that "early in the a.m" the same time as anything else? For example, EPG update?

No....EPG happens mid-day.....12:00 p.m. The crash always seems to occur between 4:00 a.m. and 5:30 a.m. It leaves the two instances of PVRX2 running.....so I have to kill them, then restart the service.

There is nothing running at that time on the sytsem....I have some backup jobs that run that use the volume shadow copy feature but they finish an hour or so before the crash occurs.

I looked at system changes and the only thing of note is I switched from AVG 8.0 to Avast Home 4.8.........but I can't directly correlate that change to when this started.....I switched to Avast about 2 weeks before this started occurring.

[sub]

For the next release I've put a try/catch around the area that encounters the problem. Its not entirely clear to me what is triggering this, but hopefully this will help the app handle it gracefully.

[UncleJohnsBand]

For the next release I've put a try/catch around the area that encounters the problem. Its not entirely clear to me what is triggering this, but hopefully this will help the app handle it gracefully.

Great...thanks....sounds like a plan.

[UncleJohnsBand]

sub....it happend this a.m. while I was watching Tv before I left for work....posted log below....perhaps it will help....

Code:

2008-07-16 05:02:14.809 VERBOSE [15] Hour is currently 5. Conversions will happen between 1:00 and 6:00 2008-07-16 05:33:14.690 VERBOSE [15] Hour is currently 5. Conversions will happen between 1:00 and 6:00 2008-07-16 05:46:19.047 VERBOSE [7] RecordingFactory.LoadNext24HourEvents() 2008-07-16 05:46:19.047 VERBOSE [7] forcing refresh of next 24 hour events for capture source:3 2008-07-16 05:46:19.063 VERBOSE [7] Starting LiveTV for captureSource: 3 channel oid: 62 filename: 2008-07-16 05:46:23.594 VERBOSE [7] RenewLease 3 2008-07-16 05:46:23.594 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:46:23.594 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:46:53.624 VERBOSE [7] RenewLease 3 2008-07-16 05:46:53.624 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:46:53.624 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:47:23.654 VERBOSE [7] RenewLease 3 2008-07-16 05:47:23.654 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:47:23.670 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:47:53.685 VERBOSE [7] RenewLease 3 2008-07-16 05:47:53.685 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:47:53.685 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:48:23.715 VERBOSE [7] RenewLease 3 2008-07-16 05:48:23.715 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:48:23.715 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:48:53.745 VERBOSE [7] RenewLease 3 2008-07-16 05:48:53.745 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:48:53.745 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:49:23.776 VERBOSE [7] RenewLease 3 2008-07-16 05:49:23.776 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:49:23.776 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:49:53.790 VERBOSE [7] RenewLease 3 2008-07-16 05:49:53.790 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:49:53.790 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:50:23.805 VERBOSE [7] RenewLease 3 2008-07-16 05:50:23.805 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:50:23.805 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:50:53.820 VERBOSE [7] RenewLease 3 2008-07-16 05:50:53.820 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:50:53.820 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:51:23.850 VERBOSE [7] RenewLease 3 2008-07-16 05:51:23.850 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:51:23.850 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:51:53.896 VERBOSE [7] RenewLease 3 2008-07-16 05:51:53.896 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:51:53.896 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:52:23.879 VERBOSE [7] RenewLease 3 2008-07-16 05:52:23.879 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:52:23.879 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:52:53.925 VERBOSE [7] RenewLease 3 2008-07-16 05:52:53.925 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:52:53.956 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:52:56.550 ERROR [11] FATAL UNHANDLED EXCEPTION:: System.Net.Sockets.SocketException: Only one usage of each socket address (protocol/network address/port) is normally permitted Server stack trace: at System.Net.Sockets.Socket.DoBind(EndPoint endPointSnapshot, SocketAddress socketAddress) at System.Net.Sockets.Socket.Bind(EndPoint localEP) at Cassini.x1b6b12494b043e38.x2dcc0ca8fed1d43b() at System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs) at System.Runtime.Remoting.Messaging.StackBuilderSink.PrivateProcessMessage(RuntimeMethodHandle md, Object[] args, Object server, Int32 methodPtr, Boolean fExecuteInContext, Object[]& outArgs) at System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(IMessage msg, Int32 methodPtr, Boolean fExecuteInContext) Exception rethrown at [0]: at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg) at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type) at Cassini.x1b6b12494b043e38.x2dcc0ca8fed1d43b() at Cassini.xcdc6d50076d34ea4.x1eebd27da31f16e1(Object xf236ab116fb26f27) at System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(Object state) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(_ThreadPoolWaitCallback tpWaitCallBack) at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(Object state) 2008-07-16 05:54:57.281 ERROR [5] Found expired lease. Stopping recording. 2008-07-16 05:54:57.390 VERBOSE [7] RenewLease 3 2008-07-16 05:54:57.390 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:54:57.515 VERBOSE [7] RenewLease finished (accepted - preview mode) 2008-07-16 05:54:58.655 VERBOSE [7] RenewLease 3 2008-07-16 05:54:58.655 VERBOSE [7] forcing refresh of next 2 hour events for all capture sources 2008-07-16 05:54:58.655 VERBOSE [7] RenewLease finished (accepted - preview mode)

[sub]

Try the attached patch and let me know.

[UncleJohnsBand]

Try the attached patch and let me know.

Ok...loaded up....we'll see what happens.