2015-10-12, 10:58
Hi All,
I'm been having a constant problem through the last few iterations of Kodi playing Live TV using Argus as a back end. After a varying amount of time (say 1/2 hour to an hour), playback freezes, the OSD says buffering, but when buffering reaches 100% playback stops and returns to the main menu screen. I've tried a variety of fixes such as setting <minvideocachelevel>15</minvideocachelevel> and <minaudiocachelevel>15</minaudiocachelevel> but these were suggestions for slightly different problems. The issue occurs across all Kodi clients which are all up to date running 15.1. Ensure Argus plugin up to date on all. The logs don't seem to give away much except that (to me) it seems like it might be something on the Kodi side given the Argus logs simply say stream started, stream stopped. Following are the key lines from the logs from playback to the freeze/stop. I can't seem to find any relation between the Kodi log errors/warnings and what might be going on with Live TV playback. Also, this issue is not experienced with any other kind of video playback, including playing back recorded programs through Argus. Any ideas greatly appreciated!
Kodi Log
17:47:20 T:5092 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
17:47:21 T:5504 WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available
17:47:22 T:2924 NOTICE: Thread JobWorker start, auto delete: true
17:47:22 T:6608 NOTICE: Thread LanguageInvoker start, auto delete: false
17:47:22 T:6608 NOTICE: -->Python Interpreter Initialized<--
17:47:22 T:8240 NOTICE: Thread LanguageInvoker start, auto delete: false
17:47:22 T:8240 NOTICE: -->Python Interpreter Initialized<--
17:47:32 T:4808 NOTICE: CDVDPlayer::OnExit()
17:47:32 T:4808 NOTICE: DVDPlayer: eof, waiting for queues to empty
17:47:32 T:4808 NOTICE: Closing stream player 1
17:47:32 T:4808 NOTICE: CDVDMessageQueue(audio)::WaitUntilEmpty
17:47:32 T:5092 ERROR: CDVDPlayerAudio:
ecodeFrame - Decode Error. Skipping audio packet (-1094995529)
17:47:32 T:5092 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
17:47:32 T:4808 NOTICE: Waiting for audio thread to exit
17:47:32 T:5092 NOTICE: thread end: CDVDPlayerAudio::OnExit()
17:47:32 T:4808 NOTICE: Closing audio device
17:47:32 T:4808 NOTICE: Deleting audio codec
17:47:32 T:4808 NOTICE: Closing stream player 2
17:47:32 T:4808 NOTICE: CDVDMessageQueue(video)::WaitUntilEmpty
17:47:32 T:5504 WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available
17:47:32 T:5504 ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true
17:47:32 T:4808 NOTICE: waiting for video thread to exit
17:47:32 T:5504 NOTICE: thread end: video_thread
17:47:32 T:4808 NOTICE: deleting video codec
17:47:32 T:4808 NOTICE: DXVA::CDecoder::Close - closing decoder
17:47:32 T:4808 NOTICE: DXVA::Close - closing decoder context
17:47:32 T:4808 NOTICE: Closing stream player 4
17:47:32 T:4808 NOTICE: CDVDMessageQueue(teletext)::WaitUntilEmpty
17:47:32 T:4808 NOTICE: waiting for teletext data thread to exit
17:47:32 T:8284 ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true (-1)
17:47:32 T:8284 NOTICE: thread end: data_thread
17:47:33 T:3208 NOTICE: CDVDPlayer::CloseFile()
17:47:33 T:3208 NOTICE: DVDPlayer: waiting for threads to exit
17:47:33 T:3208 NOTICE: DVDPlayer: finished waiting
17:47:33 T:3208 NOTICE: CDVDPlayer::CloseFile()
17:47:33 T:3208 NOTICE: DVDPlayer: waiting for threads to exit
17:47:33 T:3208 NOTICE: DVDPlayer: finished waiting
17:47:34 T:7816 NOTICE: Skin Helper Service --> Started Background worker...
17:47:34 T:7748 NOTICE: Thread LanguageInvoker start, auto delete: false
17:47:34 T:7748 NOTICE: -->Python Interpreter Initialized<--
17:47:35 T:5920 NOTICE: Thread LanguageInvoker start, auto delete: false
17:47:35 T:5920 NOTICE: -->Python Interpreter Initialized<--
17:47:35 T:7816 NOTICE: Skin Helper Service --> Ended Background worker...
17:51:19 T:4984 NOTICE: Thread JobWorker start, auto delete: true
Recorder Card Log
2015-10-12 16:59:05.8354 [Debug][Graph]: Stream started
2015-10-12 17:47:33.1231 [Debug][Graph]: Stopping stream for service 0x0001
2015-10-12 17:47:33.1231 [Info ][Graph]: Live streaming ended for WIN Darling Downs to rtsp://BELLMEDIA:8554/stream-live-2-1
2015-10-12 17:47:33.1231 [Debug][Graph]: Stopping graph
2015-10-12 17:47:49.1653 [Info ][Graph]: Tuning to 7 Digital 1
2015-10-12 17:47:49.1653 [Info ][Graph]: Tuning to 571500 7MHz RateNotDefined ModNotSet
2015-10-12 17:47:49.1653 [Debug][Graph]: Starting graph
2015-10-12 17:47:52.1749 [Info ][Graph]: Signal locked, quality: 10%, strength: 60
2015-10-12 17:47:52.1749 [Debug][Graph]: Starting EPG grabbing for service 0x0971, PID 0x971
2015-10-12 17:47:52.1799 [Info ][Graph]: EPG grabbing started
2015-10-12 17:48:50.7951 [Debug][Graph]: Stopping stream for service 0x0971
2015-10-12 17:48:50.7951 [Info ][Graph]: EPG grabbing ended on 7 Digital 1
2015-10-12 17:48:50.7951 [Debug][Graph]: Stopping graph
2015-10-12 17:48:50.8089 [Info ][Graph]: Tuning to ABC Jazz
2015-10-12 17:48:50.8089 [Info ][Graph]: Tuning to 578500 7MHz RateNotDefined ModNotSet
2015-10-12 17:48:50.8089 [Debug][Graph]: Starting graph
2015-10-12 17:48:53.8446 [Info ][Graph]: Signal locked, quality: 10%, strength: 65
2015-10-12 17:48:53.8446 [Debug][Graph]: Starting EPG grabbing for service 0x02c7, PID 0x2c7
2015-10-12 17:48:53.8446 [Info ][Graph]: EPG grabbing started
2015-10-12 17:49:53.8955 [Debug][Graph]: Stopping stream for service 0x02c7
2015-10-12 17:49:53.8985 [Info ][Graph]: EPG grabbing ended on ABC Jazz
2015-10-12 17:49:53.8985 [Debug][Graph]: Stopping graph
2015-10-12 17:49:53.8985 [Info ][Graph]: Tuning to GEM Darling Downs
2015-10-12 17:49:53.9179 [Info ][Graph]: Tuning to 592500 7MHz RateNotDefined ModNotSet
2015-10-12 17:49:53.9179 [Debug][Graph]: Starting graph
2015-10-12 17:49:56.9522 [Info ][Graph]: Signal locked, quality: 10%, strength: 60
2015-10-12 17:49:56.9522 [Debug][Graph]: Starting EPG grabbing for service 0x000a, PID 0x0a
2015-10-12 17:49:56.9522 [Info ][Graph]: EPG grabbing started
2015-10-12 17:50:45.9153 [Debug][Graph]: Stopping stream for service 0x000a
2015-10-12 17:50:45.9153 [Info ][Graph]: EPG grabbing ended on GEM Darling Downs
2015-10-12 17:50:45.9293 [Debug][Graph]: Stopping graph
2015-10-12 17:50:45.9293 [Info ][Graph]: Tuning to ELEVEN
2015-10-12 17:50:45.9293 [Info ][Graph]: Tuning to 599500 7MHz RateNotDefined ModNotSet
2015-10-12 17:50:45.9293 [Debug][Graph]: Starting graph
2015-10-12 17:50:48.9103 [Info ][Graph]: Signal locked, quality: 10%, strength: 59
2015-10-12 17:50:48.9103 [Debug][Graph]: Starting EPG grabbing for service 0x0850, PID 0x850
2015-10-12 17:50:48.9153 [Info ][Graph]: EPG grabbing started
2015-10-12 17:51:38.1215 [Debug][Graph]: Stopping stream for service 0x0850
2015-10-12 17:51:38.1215 [Info ][Graph]: EPG grabbing ended on ELEVEN
2015-10-12 17:51:38.1215 [Debug][Graph]: Stopping graph
Recorder Log
2015-10-12 16:59:05.8485 [Info ][Recorder]: Live stream 40d2b2e9-6515-4cce-83f2-7e515e4ad4a5 on card #2 tuned to WIN Darling Downs
2015-10-12 17:47:33.1040 [Info ][Recorder]: Stopping stream 40d2b2e9-6515-4cce-83f2-7e515e4ad4a5 on card #2
2015-10-12 17:47:33.1410 [Info ][Recorder]: Stream 40d2b2e9-6515-4cce-83f2-7e515e4ad4a5 stopped
Cheers!
I'm been having a constant problem through the last few iterations of Kodi playing Live TV using Argus as a back end. After a varying amount of time (say 1/2 hour to an hour), playback freezes, the OSD says buffering, but when buffering reaches 100% playback stops and returns to the main menu screen. I've tried a variety of fixes such as setting <minvideocachelevel>15</minvideocachelevel> and <minaudiocachelevel>15</minaudiocachelevel> but these were suggestions for slightly different problems. The issue occurs across all Kodi clients which are all up to date running 15.1. Ensure Argus plugin up to date on all. The logs don't seem to give away much except that (to me) it seems like it might be something on the Kodi side given the Argus logs simply say stream started, stream stopped. Following are the key lines from the logs from playback to the freeze/stop. I can't seem to find any relation between the Kodi log errors/warnings and what might be going on with Live TV playback. Also, this issue is not experienced with any other kind of video playback, including playing back recorded programs through Argus. Any ideas greatly appreciated!
Kodi Log
17:47:20 T:5092 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
17:47:21 T:5504 WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available
17:47:22 T:2924 NOTICE: Thread JobWorker start, auto delete: true
17:47:22 T:6608 NOTICE: Thread LanguageInvoker start, auto delete: false
17:47:22 T:6608 NOTICE: -->Python Interpreter Initialized<--
17:47:22 T:8240 NOTICE: Thread LanguageInvoker start, auto delete: false
17:47:22 T:8240 NOTICE: -->Python Interpreter Initialized<--
17:47:32 T:4808 NOTICE: CDVDPlayer::OnExit()
17:47:32 T:4808 NOTICE: DVDPlayer: eof, waiting for queues to empty
17:47:32 T:4808 NOTICE: Closing stream player 1
17:47:32 T:4808 NOTICE: CDVDMessageQueue(audio)::WaitUntilEmpty
17:47:32 T:5092 ERROR: CDVDPlayerAudio:
ecodeFrame - Decode Error. Skipping audio packet (-1094995529)17:47:32 T:5092 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
17:47:32 T:4808 NOTICE: Waiting for audio thread to exit
17:47:32 T:5092 NOTICE: thread end: CDVDPlayerAudio::OnExit()
17:47:32 T:4808 NOTICE: Closing audio device
17:47:32 T:4808 NOTICE: Deleting audio codec
17:47:32 T:4808 NOTICE: Closing stream player 2
17:47:32 T:4808 NOTICE: CDVDMessageQueue(video)::WaitUntilEmpty
17:47:32 T:5504 WARNING: CDVDMessageQueue(video)::Get - asked for new data packet, with nothing available
17:47:32 T:5504 ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true
17:47:32 T:4808 NOTICE: waiting for video thread to exit
17:47:32 T:5504 NOTICE: thread end: video_thread
17:47:32 T:4808 NOTICE: deleting video codec
17:47:32 T:4808 NOTICE: DXVA::CDecoder::Close - closing decoder
17:47:32 T:4808 NOTICE: DXVA::Close - closing decoder context
17:47:32 T:4808 NOTICE: Closing stream player 4
17:47:32 T:4808 NOTICE: CDVDMessageQueue(teletext)::WaitUntilEmpty
17:47:32 T:4808 NOTICE: waiting for teletext data thread to exit
17:47:32 T:8284 ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true (-1)
17:47:32 T:8284 NOTICE: thread end: data_thread
17:47:33 T:3208 NOTICE: CDVDPlayer::CloseFile()
17:47:33 T:3208 NOTICE: DVDPlayer: waiting for threads to exit
17:47:33 T:3208 NOTICE: DVDPlayer: finished waiting
17:47:33 T:3208 NOTICE: CDVDPlayer::CloseFile()
17:47:33 T:3208 NOTICE: DVDPlayer: waiting for threads to exit
17:47:33 T:3208 NOTICE: DVDPlayer: finished waiting
17:47:34 T:7816 NOTICE: Skin Helper Service --> Started Background worker...
17:47:34 T:7748 NOTICE: Thread LanguageInvoker start, auto delete: false
17:47:34 T:7748 NOTICE: -->Python Interpreter Initialized<--
17:47:35 T:5920 NOTICE: Thread LanguageInvoker start, auto delete: false
17:47:35 T:5920 NOTICE: -->Python Interpreter Initialized<--
17:47:35 T:7816 NOTICE: Skin Helper Service --> Ended Background worker...
17:51:19 T:4984 NOTICE: Thread JobWorker start, auto delete: true
Recorder Card Log
2015-10-12 16:59:05.8354 [Debug][Graph]: Stream started
2015-10-12 17:47:33.1231 [Debug][Graph]: Stopping stream for service 0x0001
2015-10-12 17:47:33.1231 [Info ][Graph]: Live streaming ended for WIN Darling Downs to rtsp://BELLMEDIA:8554/stream-live-2-1
2015-10-12 17:47:33.1231 [Debug][Graph]: Stopping graph
2015-10-12 17:47:49.1653 [Info ][Graph]: Tuning to 7 Digital 1
2015-10-12 17:47:49.1653 [Info ][Graph]: Tuning to 571500 7MHz RateNotDefined ModNotSet
2015-10-12 17:47:49.1653 [Debug][Graph]: Starting graph
2015-10-12 17:47:52.1749 [Info ][Graph]: Signal locked, quality: 10%, strength: 60
2015-10-12 17:47:52.1749 [Debug][Graph]: Starting EPG grabbing for service 0x0971, PID 0x971
2015-10-12 17:47:52.1799 [Info ][Graph]: EPG grabbing started
2015-10-12 17:48:50.7951 [Debug][Graph]: Stopping stream for service 0x0971
2015-10-12 17:48:50.7951 [Info ][Graph]: EPG grabbing ended on 7 Digital 1
2015-10-12 17:48:50.7951 [Debug][Graph]: Stopping graph
2015-10-12 17:48:50.8089 [Info ][Graph]: Tuning to ABC Jazz
2015-10-12 17:48:50.8089 [Info ][Graph]: Tuning to 578500 7MHz RateNotDefined ModNotSet
2015-10-12 17:48:50.8089 [Debug][Graph]: Starting graph
2015-10-12 17:48:53.8446 [Info ][Graph]: Signal locked, quality: 10%, strength: 65
2015-10-12 17:48:53.8446 [Debug][Graph]: Starting EPG grabbing for service 0x02c7, PID 0x2c7
2015-10-12 17:48:53.8446 [Info ][Graph]: EPG grabbing started
2015-10-12 17:49:53.8955 [Debug][Graph]: Stopping stream for service 0x02c7
2015-10-12 17:49:53.8985 [Info ][Graph]: EPG grabbing ended on ABC Jazz
2015-10-12 17:49:53.8985 [Debug][Graph]: Stopping graph
2015-10-12 17:49:53.8985 [Info ][Graph]: Tuning to GEM Darling Downs
2015-10-12 17:49:53.9179 [Info ][Graph]: Tuning to 592500 7MHz RateNotDefined ModNotSet
2015-10-12 17:49:53.9179 [Debug][Graph]: Starting graph
2015-10-12 17:49:56.9522 [Info ][Graph]: Signal locked, quality: 10%, strength: 60
2015-10-12 17:49:56.9522 [Debug][Graph]: Starting EPG grabbing for service 0x000a, PID 0x0a
2015-10-12 17:49:56.9522 [Info ][Graph]: EPG grabbing started
2015-10-12 17:50:45.9153 [Debug][Graph]: Stopping stream for service 0x000a
2015-10-12 17:50:45.9153 [Info ][Graph]: EPG grabbing ended on GEM Darling Downs
2015-10-12 17:50:45.9293 [Debug][Graph]: Stopping graph
2015-10-12 17:50:45.9293 [Info ][Graph]: Tuning to ELEVEN
2015-10-12 17:50:45.9293 [Info ][Graph]: Tuning to 599500 7MHz RateNotDefined ModNotSet
2015-10-12 17:50:45.9293 [Debug][Graph]: Starting graph
2015-10-12 17:50:48.9103 [Info ][Graph]: Signal locked, quality: 10%, strength: 59
2015-10-12 17:50:48.9103 [Debug][Graph]: Starting EPG grabbing for service 0x0850, PID 0x850
2015-10-12 17:50:48.9153 [Info ][Graph]: EPG grabbing started
2015-10-12 17:51:38.1215 [Debug][Graph]: Stopping stream for service 0x0850
2015-10-12 17:51:38.1215 [Info ][Graph]: EPG grabbing ended on ELEVEN
2015-10-12 17:51:38.1215 [Debug][Graph]: Stopping graph
Recorder Log
2015-10-12 16:59:05.8485 [Info ][Recorder]: Live stream 40d2b2e9-6515-4cce-83f2-7e515e4ad4a5 on card #2 tuned to WIN Darling Downs
2015-10-12 17:47:33.1040 [Info ][Recorder]: Stopping stream 40d2b2e9-6515-4cce-83f2-7e515e4ad4a5 on card #2
2015-10-12 17:47:33.1410 [Info ][Recorder]: Stream 40d2b2e9-6515-4cce-83f2-7e515e4ad4a5 stopped
Cheers!
