search

fetzerch / xbmc-pvr-addons

XBMC PVR add-ons
GNU General Public License v3.0
19 stars 17 forks source link

Occasional hang when initiating playback #139

Closed willat8 closed 11 years ago

willat8 commented 11 years ago

Hi, I'm running fixes/0.27 mythbackend and the latest myth add on from the xbmc nightlies.

This is the chain of actions I do:

  1. Enter a recording folder with multiple recordings
  2. Press enter to begin playback of one recording
  3. Stop playback, taking me back to the recordings folder
  4. Immediately select another recording to playback in that same folder

At this point, about 50% of the time, I will get a large ~1 minute hang where XBMC stops responding. After this time the playback will start and a message "The backend does not support this action" appears, although everything seems to working after the wait.

If after stopping playback in step 3 I navigate back to the main recordings list and select another recordings folder and then play a recording in that folder I get no hang.

Attached is relevant log with all activity in the minute hang, can provide more since bug is quite easily reproducible. Bug appears on my 3 Raspberry Pis and Windows (the only XBMCs I use).

09:13:01 T:5004   DEBUG: AddOnLog: MythTV cmyth PVR Client: PVRClientMythTV::GetRecordingLastPlayedPosition - Reading Bookmark for: Big Brother - Live Intruders Special
09:13:06 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length
09:13:06 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length: buffer is '82      ' ret = 82
09:13:06 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'BACKEND_MESSAGE'
09:13:06 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'UPDATE_FILE_SIZE 1009 2013-10-01T23:00:00Z 566901216'
09:13:06 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_data: string received 'emptyE_FILE_SIZE 1009 2013-10-01T23:00:00Z 566901216'
09:13:06 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_event_get_message: leftover data: count 5, read 5, errno 0
09:13:06 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - EVENT ID: CMYTH_EVENT_UPDATE_FILE_SIZE, EVENT databuf: 1009 2013-10-01T23:00:00Z 566901216
09:13:06 T:3632  NOTICE: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - Event file size update: 1009 2013-10-01T23:00:00Z 566901216
09:13:16 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length
09:13:16 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length: buffer is '82      ' ret = 82
09:13:16 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'BACKEND_MESSAGE'
09:13:16 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'UPDATE_FILE_SIZE 1009 2013-10-01T23:00:00Z 573459408'
09:13:16 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_data: string received 'emptyE_FILE_SIZE 1009 2013-10-01T23:00:00Z 573459408'
09:13:16 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_event_get_message: leftover data: count 5, read 5, errno 0
09:13:16 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - EVENT ID: CMYTH_EVENT_UPDATE_FILE_SIZE, EVENT databuf: 1009 2013-10-01T23:00:00Z 573459408
09:13:16 T:3632  NOTICE: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - Event file size update: 1009 2013-10-01T23:00:00Z 573459408
09:13:26 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length
09:13:26 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length: buffer is '82      ' ret = 82
09:13:26 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'BACKEND_MESSAGE'
09:13:26 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'UPDATE_FILE_SIZE 1009 2013-10-01T23:00:00Z 579655512'
09:13:26 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_data: string received 'emptyE_FILE_SIZE 1009 2013-10-01T23:00:00Z 579655512'
09:13:26 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_event_get_message: leftover data: count 5, read 5, errno 0
09:13:26 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - EVENT ID: CMYTH_EVENT_UPDATE_FILE_SIZE, EVENT databuf: 1009 2013-10-01T23:00:00Z 579655512
09:13:26 T:3632  NOTICE: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - Event file size update: 1009 2013-10-01T23:00:00Z 579655512
09:13:30 T:3800   ERROR: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_okay: cmyth_rcv_length() failed
09:13:30 T:3800   ERROR: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_set_bookmark: cmyth_rcv_okay() failed
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: Unlock 85525256
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: Lock 85525256
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: Lock acquired 85525256
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: Unlock 85525256
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: MythConnection::IsConnected - false
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: Lock 85525256
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: Lock acquired 85525256
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_conn_reconnect_monitor: reconnecting monitor connection
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_reconnect_addr: setting socket option SO_RCVBUF to 128000
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_reconnect_addr: connecting to titan:6543 fd = 1228
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_send_message
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_send_message: sending message '30      MYTH_PROTO_VERSION 77 WindMark'
09:13:30 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length
09:13:30 T:3632   DEBUG: Previous line repeats 1 times.
09:13:30 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length: buffer is '91      ' ret = 91
09:13:30 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'BACKEND_MESSAGE'
09:13:30 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'SYSTEM_EVENT CLIENT_DISCONNECTED HOSTNAME trumpe SENDER titan'
09:13:30 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_data: string received 'emptyM_EVENT CLIENT_DISCONNECTED HOSTNAME trumpe SENDER titan'
09:13:30 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_event_get_message: leftover data: count 5, read 5, errno 0
09:13:30 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - EVENT ID: CMYTH_EVENT_SYSTEM_EVENT, EVENT databuf: CLIENT_DISCONNECTED HOSTNAME trumpe SENDER titan
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length: buffer is '13      ' ret = 13
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'ACCEPT'
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received '77'
09:13:30 T:3800   ERROR: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_conn_reconnect: asked for version 77, got version 77
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_conn_reconnect: agreed on Version 77 protocol
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_send_message
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_send_message: sending message '20      ANN Monitor trumpe 0'
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length: buffer is '2       ' ret = 2
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'OK'
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_conn_reconnect_monitor: done reconnecting monitor connection ret = 1
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: Unlock 85525256
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: Lock 85525256
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: Lock acquired 85525256
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_send_message
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_send_message: sending message '35      SET_BOOKMARK 1099 1380437940 7675 0'
09:13:30 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length
09:13:30 T:3380   DEBUG: Thread JobWorker 3380 terminating (autodelete)
09:13:30 T:2804   DEBUG: Thread JobWorker 2804 terminating (autodelete)
09:13:36 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length
09:13:36 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length: buffer is '82      ' ret = 82
09:13:36 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'BACKEND_MESSAGE'
09:13:36 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'UPDATE_FILE_SIZE 1009 2013-10-01T23:00:00Z 586569400'
09:13:36 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_data: string received 'emptyE_FILE_SIZE 1009 2013-10-01T23:00:00Z 586569400'
09:13:36 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_event_get_message: leftover data: count 5, read 5, errno 0
09:13:36 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - EVENT ID: CMYTH_EVENT_UPDATE_FILE_SIZE, EVENT databuf: 1009 2013-10-01T23:00:00Z 586569400
09:13:36 T:3632  NOTICE: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - Event file size update: 1009 2013-10-01T23:00:00Z 586569400
09:13:46 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length
09:13:46 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length: buffer is '82      ' ret = 82
09:13:46 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'BACKEND_MESSAGE'
09:13:46 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'UPDATE_FILE_SIZE 1009 2013-10-01T23:00:00Z 594116096'
09:13:46 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_data: string received 'emptyE_FILE_SIZE 1009 2013-10-01T23:00:00Z 594116096'
09:13:46 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_event_get_message: leftover data: count 5, read 5, errno 0
09:13:46 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - EVENT ID: CMYTH_EVENT_UPDATE_FILE_SIZE, EVENT databuf: 1009 2013-10-01T23:00:00Z 594116096
09:13:46 T:3632  NOTICE: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - Event file size update: 1009 2013-10-01T23:00:00Z 594116096
09:13:56 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length
09:13:56 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_length: buffer is '82      ' ret = 82
09:13:56 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'BACKEND_MESSAGE'
09:13:56 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_string: string received 'UPDATE_FILE_SIZE 1009 2013-10-01T23:00:00Z 599600808'
09:13:56 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_data: string received 'emptyE_FILE_SIZE 1009 2013-10-01T23:00:00Z 599600808'
09:13:56 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_event_get_message: leftover data: count 5, read 5, errno 0
09:13:56 T:3632   DEBUG: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - EVENT ID: CMYTH_EVENT_UPDATE_FILE_SIZE, EVENT databuf: 1009 2013-10-01T23:00:00Z 599600808
09:13:56 T:3632  NOTICE: AddOnLog: MythTV cmyth PVR Client: MythEventHandler::MythEventHandlerPrivate::Process - Event file size update: 1009 2013-10-01T23:00:00Z 599600808
09:14:00 T:3800   ERROR: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)__cmyth_rcv_okay: cmyth_rcv_length() failed
09:14:00 T:3800   ERROR: AddOnLog: MythTV cmyth PVR Client: LibCMyth: (cmyth)cmyth_set_bookmark: cmyth_rcv_okay() failed
09:14:00 T:3800   DEBUG: AddOnLog: MythTV cmyth PVR Client: Unlock 85525256
09:14:00 T:3800   ERROR: AddOnLog: MythTV cmyth PVR Client: PVRClientMythTV::SetRecordingLastPlayedPosition - Setting Bookmark failed
nerddtvg commented 11 years ago

This is due to a protocol change removing a parameter for SET_BOOKMARK inside MythTV 0.27. The code in the PR should resolve this issue. Please test it out if you are able to do so.

fetzerch commented 11 years ago

Fix in #140 is now available in branches master and frodo. Thanks