Status incorrectly set to idle when error handler runs

[smarquard]

In a case where galicaster does not initialize properly (or possibly some error happens and it goes into error state), the error handler can incorrectly reset the status which is set to the server to idle, so as far as Opencast is concerned, the CA is fine whereas in fact it's in a continuous error loop.

The status should not be idle here unless the CA is actually started and fully operational.

If this is a startup issue, it would be fine for the CA status to be "unknown" until it's actually started fully in which case it goes either to idle (fine) or error (can't record).

galicaster      2017-03-29 06:31:06,908 DEBUG   recorder/recorder       Init bin audio galicaster.recorder.bins.pulse
galicaster      2017-03-29 06:31:06,909 DEBUG   recorder/utils  Audio sink: sink-audio -> alsasink
galicaster      2017-03-29 06:31:06,971 DEBUG   recorder/recorder       'NoneType' object has no attribute 'set_property'
galicaster      2017-03-29 06:31:06,975 DEBUG   recorder/recorder       recorder preview
galicaster      2017-03-29 06:31:16,987 ERROR   recorder/recorder       Timeout getting recorder status, current status: (<enum GST_STATE_CHANGE_ASYNC of type Gst.StateChangeReturn>, state=<enum GST_STATE_PAUSED of type Gst.State>, pending=<enum GST_STATE_PLAYING of type Gst.State>)
galicaster      2017-03-29 06:31:16,987 ERROR   recorder/service        Handle error (Timeout getting recorder status, current status: (<enum GST_STATE_CHANGE_ASYNC of type Gst.StateChangeReturn>, state=<enum GST_STATE_PAUSED of type Gst.State>, pending=<enum GST_STATE_PLAYING of type Gst.State>))
galicaster      2017-03-29 06:31:26,987 DEBUG   recorder/recorder       Resume recorder before stopping
galicaster      2017-03-29 06:31:26,987 DEBUG   recorder/recorder       recorder resumed
galicaster      2017-03-29 06:31:37,090 DEBUG   recorder/service        Connecting recover recorder callback
galicaster      2017-03-29 06:31:37,090 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-03-29 06:31:37,091 INFO    opencast/service        Init opencast client
galicaster      2017-03-29 06:31:37,098 INFO    opencast/service        Be careful using profiles and opencast scheduler
galicaster      2017-03-29 06:31:37,099 DEBUG   opencast/service        Updating series from server
galicaster      2017-03-29 06:31:46,996 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-03-29 06:31:46,996 INFO    opencast/service        Set status idle to server
galicaster      2017-03-29 06:31:46,996 INFO    opencast/client Sending state idle
galicaster      2017-03-29 06:31:56,996 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-03-29 06:31:56,996 INFO    opencast/service        Set status idle to server
galicaster      2017-03-29 06:31:56,996 INFO    opencast/client Sending state idle
galicaster      2017-03-29 06:32:03,996 INFO    recorder/service        Handle recover from error
galicaster      2017-03-29 06:32:03,996 INFO    opencast/service        Process ical
galicaster      2017-03-29 06:32:03,996 DEBUG   scheduler/heartbeat     galicaster-notify-long in 60
galicaster      2017-03-29 06:32:04,600 INFO    opencast/client iCal modified
galicaster      2017-03-29 06:32:04,626 DEBUG   opencast/service        Updating series from server
galicaster      2017-03-29 06:32:06,996 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-03-29 06:32:06,996 INFO    opencast/service        Set status idle to server
galicaster      2017-03-29 06:32:06,996 INFO    opencast/client Sending state idle
galicaster      2017-03-29 06:32:16,996 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-03-29 06:32:16,996 INFO    opencast/service        Set status idle to server
galicaster      2017-03-29 06:32:16,996 INFO    opencast/client Sending state idle
galicaster      2017-03-29 06:32:26,995 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-03-29 06:32:26,996 INFO    opencast/service        Set status idle to server
galicaster      2017-03-29 06:32:26,996 INFO    opencast/client Sending state idle
galicaster      2017-03-29 06:32:36,996 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-03-29 06:32:36,996 INFO    opencast/service        Set status idle to server
galicaster      2017-03-29 06:32:36,996 INFO    opencast/client Sending state idle
galicaster      2017-03-29 06:32:46,996 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-03-29 06:32:46,996 INFO    opencast/service        Set status idle to server
galicaster      2017-03-29 06:32:46,996 INFO    opencast/client Sending state idle
galicaster      2017-03-29 06:32:56,996 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-03-29 06:32:56,996 INFO    opencast/service        Set status idle to server
galicaster      2017-03-29 06:32:56,996 INFO    opencast/client Sending state idle
galicaster      2017-03-29 06:33:03,996 INFO    recorder/service        Handle recover from error

[smarquard]

We don't know the underlying cause of the "Timeout getting recorder status" failed startup, but that's another issue.

[smarquard]

This change seems to have broken the auto-recover.

Tested on a CA in idle state. Reboot the IP camera (so the rtsp connection is broken). The camera comes back online, but the CA never switches out of error state.

galicaster      2017-04-18 10:28:05,655 INFO    recorder/service        Starting recording service in the preview status
galicaster      2017-04-18 10:28:05,655 INFO    recorder/service        Using profile with name Default and path /usr/share/galicaster/conf-d                                                                        ist.ini
galicaster      2017-04-18 10:28:05,655 DEBUG   recorder/recorder       Init bin presenter galicaster.recorder.bins.rtp
galicaster      2017-04-18 10:28:05,657 DEBUG   recorder/utils  Video sink: sink-presenter -> xvimagesink
galicaster      2017-04-18 10:28:05,657 DEBUG   recorder/utils  Audio sink: sink-audio-presenter -> alsasink
galicaster      2017-04-18 10:28:05,659 DEBUG   recorder/recorder       Init bin presentation galicaster.recorder.bins.blackmagic
galicaster      2017-04-18 10:28:05,660 DEBUG   recorder/utils  Video sink: sink-presentation -> xvimagesink
galicaster      2017-04-18 10:28:05,661 DEBUG   recorder/utils  Audio sink: sink-audio-presentation -> alsasink
galicaster      2017-04-18 10:28:05,698 INFO    opencast/service        Process ical
galicaster      2017-04-18 10:28:05,703 DEBUG   recorder/recorder       Init bin presentation2 galicaster.recorder.bins.blackmagic
galicaster      2017-04-18 10:28:05,703 DEBUG   recorder/utils  Video sink: sink-presentation2 -> xvimagesink
galicaster      2017-04-18 10:28:05,703 DEBUG   recorder/utils  Audio sink: sink-audio-presentation2 -> alsasink
galicaster      2017-04-18 10:28:05,709 INFO    opencast/client iCal Not modified
galicaster      2017-04-18 10:28:05,734 DEBUG   recorder/recorder       Init bin audio galicaster.recorder.bins.pulse
galicaster      2017-04-18 10:28:05,735 DEBUG   recorder/utils  Audio sink: sink-audio -> alsasink
galicaster      2017-04-18 10:28:05,822 INFO    opencast/service        Updating series from server
galicaster      2017-04-18 10:28:05,825 DEBUG   scheduler/heartbeat     galicaster-notify-long in 60
galicaster      2017-04-18 10:28:15,653 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-04-18 10:28:15,654 INFO    opencast/service        Set status unknown to server
galicaster      2017-04-18 10:28:15,654 INFO    opencast/client Sending state unknown

[smarquard]

[smarquard]

Should be tested along with #473 as these are different aspects of the error handling.

[smarquard]

Thanks, the latest commits have fixed this issue for us. Autorecover is working correctly.

[smarquard]

So autorecover works correctly now but there's still a timing issue with sending a status idle.

Here's an example from a CA where the IP cam is made unavailable while GC is in preview.

At 11:53:43,709 there's a "status idle" which is misleading - the CA has tried auto-recover, preview starts, then it sends idle but the error is triggered again shortly afterwards because the IP cam is not actually available.

So I would say there should be some delay after a preview starts before updating the status otherwise the "idle" here is misleading.

It's not a serious issue though so if there's no easy way to handle this correctly, we could live with the current behaviour.

galicaster      2017-04-21 11:53:33,710 INFO    opencast/service        Set status unknown to server
galicaster      2017-04-21 11:53:33,710 INFO    opencast/client Sending state unknown
galicaster      2017-04-21 11:53:42,710 INFO    recorder/service        Handle recover from error
galicaster      2017-04-21 11:53:42,710 INFO    recorder/service        Disconnecting recover recorder callback
galicaster      2017-04-21 11:53:42,710 INFO    opencast/service        Process ical
galicaster      2017-04-21 11:53:42,711 DEBUG   scheduler/heartbeat     galicaster-notify-long in 60
galicaster      2017-04-21 11:53:42,711 INFO    recorder/service        Resetting recorder after reloading the profile
galicaster      2017-04-21 11:53:42,711 INFO    recorder/service        Starting recording service in the preview status
galicaster      2017-04-21 11:53:42,711 INFO    recorder/service        Using profile with name Default and path /usr/share/galicaster/conf-dist.ini
galicaster      2017-04-21 11:53:42,711 DEBUG   recorder/recorder       Init bin presenter galicaster.recorder.bins.rtp
galicaster      2017-04-21 11:53:42,712 DEBUG   recorder/utils  Video sink: sink-presenter -> xvimagesink
galicaster      2017-04-21 11:53:42,712 DEBUG   recorder/utils  Audio sink: sink-audio-presenter -> alsasink
galicaster      2017-04-21 11:53:42,713 DEBUG   recorder/recorder       Init bin presentation galicaster.recorder.bins.blackmagic
galicaster      2017-04-21 11:53:42,713 DEBUG   recorder/utils  Video sink: sink-presentation -> xvimagesink
galicaster      2017-04-21 11:53:42,713 DEBUG   recorder/utils  Audio sink: sink-audio-presentation -> alsasink
galicaster      2017-04-21 11:53:42,718 INFO    opencast/client iCal Not modified
galicaster      2017-04-21 11:53:42,754 DEBUG   recorder/recorder       Init bin presentation2 galicaster.recorder.bins.blackmagic
galicaster      2017-04-21 11:53:42,755 DEBUG   recorder/utils  Video sink: sink-presentation2 -> xvimagesink
galicaster      2017-04-21 11:53:42,755 DEBUG   recorder/utils  Audio sink: sink-audio-presentation2 -> alsasink
galicaster      2017-04-21 11:53:42,811 INFO    opencast/service        Updating series from server
galicaster      2017-04-21 11:53:42,812 DEBUG   recorder/recorder       Init bin audio galicaster.recorder.bins.pulse
galicaster      2017-04-21 11:53:42,812 DEBUG   recorder/utils  Audio sink: sink-audio -> alsasink
galicaster      2017-04-21 11:53:42,818 DEBUG   recorder/recorder       recorder preview
galicaster      2017-04-21 11:53:43,709 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-04-21 11:53:43,709 INFO    opencast/service        Set status idle to server
galicaster      2017-04-21 11:53:43,710 INFO    opencast/client Sending state idle
galicaster      2017-04-21 11:53:43,823 ERROR   recorder/recorder       gst-resource-error-quark: Could not open resource for reading and writing. (7) (gstrtspsrc.c(6819): gst_rtspsrc_retrieve_sdp (): /GstPipeline:galicaster_recorder/galicaster+recorder+bins+rtp+GCrtp:galicaster+recorder+bins+rtp+gcrtp7/GstBin:bin28/GstRTSPSrc:gc-rtp-src:
Failed to connect. (Generic error))
galicaster      2017-04-21 11:53:44,923 ERROR   recorder/service        Handle error (gst-resource-error-quark: Could not open resource for reading and writing. (7) (gstrtspsrc.c(6819): gst_rtspsrc_retrieve_sdp (): /GstPipeline:galicaster_recorder/galicaster+recorder+bins+rtp+GCrtp:galicaster+recorder+bins+rtp+gcrtp7/GstBin:bin28/GstRTSPSrc:gc-rtp-src:
Failed to connect. (Generic error)))
galicaster      2017-04-21 11:53:44,923 INFO    recorder/service        Connecting recover recorder callback
galicaster      2017-04-21 11:53:53,710 DEBUG   scheduler/heartbeat     galicaster-notify-short in 10
galicaster      2017-04-21 11:53:53,711 INFO    opencast/service        Set status unknown to server
galicaster      2017-04-21 11:53:53,711 INFO    opencast/client Sending state unknown