Sometimes Kodi hangs on stopping a stream - MMAL issue

  Thread Rating:
  • 0 Vote(s) - 0 Average
  • 1
  • 2
  • 3
  • 4
  • 5
Post Reply
KlotX Offline
Member
Posts: 87
Joined: Dec 2016
Reputation: 4
Post: #1
Hi

I have some streams which are managed with pvr.iptvsimple, and occasionally when stopping a stream, it hangs on the last frame and the only possible solution is to reboot the system/restart kodi. This situation happens only after watching the same stream for a while, I can say for sure how long, but surely more than 10-15-20 min.

Current version is Raspbian's 17.1, this doesn't happen on 17.0.

kodi.log shows the following error:
Code:
00:46:44.767 T:1409491888   ERROR: CMMALVideo::dec_control_port_cb Error (status=3 EINVAL)

I've tried to enable debug but I couldn't reproduce it in any of the attempts.

Switching to OMX "fixed" the issue, but there's no image on MPEG 2 streams. Usually this error doesn't occur when stopping the stream, but sometime before, and when this shows up in the logs, for sure it will hang when stopping the stream.

I'm sorry I can't provide more info, but as I said, with debug on I was never able to reproduce it.

Maybe @popcornmix has some idea on this Smile
(This post was last modified: 2017-05-14 21:51 by KlotX.)
find quote
popcornmix Offline
Team-Kodi Member
Posts: 7,922
Joined: Feb 2011
Reputation: 331
Post: #2
I'm afraid one line of logging won't be enough.
The fact omxplayer gives no image suggests you don't have an MPG2 codec licence.
Getting one will likely improve playback (through hardware decode) and may well avoid the problem.

Otherwise I'll want a complete debug enabled log, and ideally instructions to reproduce the problem.
find quote
KlotX Offline
Member
Posts: 87
Joined: Dec 2016
Reputation: 4
Post: #3
Yes Smile

That's what I tried to do during the weekend. I've had debug enabled for MMAL and VideoPlayer components all the time during the weekend and it never happened, after 30 min with it disabled I got the error above. I'm not sure if it could be some kind of race condition that the extra time spent on the logging would masquerade.

I'll try it again with debug enabled and will update you. MMAL and VideoPlayer components debug is enough or would you advise more than that ?

And yes, there's no MPG2 licence and I assumed that's due to the licence but I forgot to mention that in the previous post.
find quote
KlotX Offline
Member
Posts: 87
Joined: Dec 2016
Reputation: 4
Post: #4
With the upgrade to 17.3 this problem never occurred again Smile something might have been fixed by one of your latest patches.

Thanks


Sent from my iPhone (typie typie)
find quote
KlotX Offline
Member
Posts: 87
Joined: Dec 2016
Reputation: 4
Post: #5
I'd like to take my last post back, this is happening and it happens often - with debug switched off.

Problem: After one day with debug on on ffmpeg and video player, there's no blocking. I stopped debug and it happened 3 times in 30 minutes. I start to believe that there's a race condition here, and logging just "fixes" that.

I'll try again tomorrow.
find quote
popcornmix Offline
Team-Kodi Member
Posts: 7,922
Joined: Feb 2011
Reputation: 331
Post: #6
It's hard to do anything about it without a debug log or instructions to reproduce (e.g. a example stream that shows the problem).
find quote
KlotX Offline
Member
Posts: 87
Joined: Dec 2016
Reputation: 4
Post: #7
(2017-07-02 14:14)popcornmix Wrote:  It's hard to do anything about it without a debug log or instructions to reproduce (e.g. a example stream that shows the problem).
I totally understand that, it was just my frustration that led me to post it here, as I can't reproduce it with debug on.

I can't share the streams for obvious reasons, but I'm trying my best to reproduce it.

Something that changed in 17.1 is causing it, prior to that version I don't have any problems.

As soon as I have more news I'll post it here.

Thanks.
(This post was last modified: 2017-07-02 14:29 by KlotX.)
find quote
KlotX Offline
Member
Posts: 87
Joined: Dec 2016
Reputation: 4
Post: #8
Hi

I think I was able to reproduce it once, although the behaviour was a bit different as Kodi crashed instead of hanging.

Here is the debug log (2.1MB)

I couldn't upload it to pastebin due to its size.

Also, I redacted all the URLs for obvious reasons Smile

Does this help ?

Regards,
find quote
KlotX Offline
Member
Posts: 87
Joined: Dec 2016
Reputation: 4
Post: #9
With debug ON only for FFMPEG I got this error again:

Code:
20:01:56.536 T:1345844144   ERROR: CMMALVideo::dec_control_port_cb Error (status=3 EINVAL)

As reported in the first post, once this shows up in the log, when I try to stop the stream Kodi hangs..

The last messages on the Log are these ones, starting with the Stop action:

Code:
21:31:49.385 T:1946092192   DEBUG: OnKey: guide (0xe0) pressed, action is Stop
21:31:49.385 T:1946092192  NOTICE: CVideoPlayer::CloseFile()
21:31:49.386 T:1946092192  NOTICE: VideoPlayer: waiting for threads to exit
21:31:49.396 T:1521480624  NOTICE: CVideoPlayer::OnExit()
21:31:49.396 T:1521480624  NOTICE: Closing stream player 1
21:31:49.396 T:1521480624  NOTICE: Waiting for audio thread to exit
21:31:49.437 T:1358951344  NOTICE: thread end: CVideoPlayerAudio::OnExit()
21:31:49.437 T:1358951344   DEBUG: Thread VideoPlayerAudio 1358951344 terminating
21:31:49.437 T:1521480624  NOTICE: Closing audio device
21:31:49.438 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] Using s16p internally between filters
21:31:49.480 T:1521480624   DEBUG: CDVDAudio::Flush - flush audio stream
21:31:49.481 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] Using s16p internally between filters
21:31:49.481 T:1925182384   DEBUG: CActiveAE::DiscardStream - audio stream deleted
21:31:49.481 T:1925182384   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
21:31:49.481 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] Using s16p internally between filters
21:31:49.481 T:1925182384   DEBUG: Previous line repeats 1 times.
21:31:49.482 T:1925182384   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
21:31:49.484 T:1521480624   DEBUG: Previous line repeats 1 times.
21:31:49.484 T:1521480624  NOTICE: Deleting audio codec
21:31:49.484 T:1521480624  NOTICE: Closing stream player 2
21:31:49.484 T:1521480624  NOTICE: waiting for video thread to exit
21:31:49.485 T:1914696624    INFO: CActiveAESink::OpenSink - initialize sink
21:31:49.485 T:1367339952  NOTICE: thread end: video_thread
21:31:49.485 T:1367339952   DEBUG: Thread VideoPlayerVideo 1367339952 terminating
21:31:49.489 T:1521480624  NOTICE: deleting video codec
21:31:49.581 T:1914696624   DEBUG: CAESinkPi:Drain delay:95ms now:0ms
21:31:49.581 T:1914696624   DEBUG: CAESinkPi:Deinitialize
21:31:49.583 T:1914696624   DEBUG: CAESinkPi:SetAudioProps hdmi_stream_channels 0 hdmi_channel_map 00000000
21:31:49.587 T:1914696624   DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.audio_render handle 0x723da900
21:31:49.588 T:1914696624   DEBUG: CActiveAESink::OpenSink - trying to open device PI:HDMI
21:31:49.588 T:1914696624   DEBUG: CAESinkPi:Initialize Format:15 Channels:2 Samplerate:44100 framesize:8 bufsize:17640 bytes/s=352800.00 dest=PI:HDMI
21:31:49.588 T:1914696624   DEBUG: CAESinkPi:SetAudioProps hdmi_stream_channels 0 hdmi_channel_map 00000008
21:31:49.590 T:1914696624   DEBUG: COMXCoreComponent::Initialize OMX.broadcom.audio_render input port 100 output port 100 m_handle 0x7237b5d0
21:31:49.592 T:1914696624   DEBUG: COMXCoreComponent::AllocInputBuffers component(OMX.broadcom.audio_render) - port(100), nBufferCountMin(1), nBufferCountActual(2), nBufferSize(17648), nBufferAlignmen(16)
21:31:49.593 T:1914696624   DEBUG: CActiveAESink::OpenSink - SinkPi Initialized:
21:31:49.593 T:1914696624   DEBUG:   Output Device : HDMI
21:31:49.593 T:1914696624   DEBUG:   Sample Rate   : 44100
21:31:49.593 T:1914696624   DEBUG:   Sample Format : AE_FMT_FLOAT
21:31:49.593 T:1914696624   DEBUG:   Channel Count : 2
21:31:49.593 T:1914696624   DEBUG:   Channel Layout: FL,FR
21:31:49.593 T:1914696624   DEBUG:   Frames        : 2205
21:31:49.593 T:1914696624   DEBUG:   Frame Size    : 8
21:31:49.599 T:1914696624   DEBUG: ffmpeg[721FF3B0]: [SWR] Using fltp internally between filters
21:31:49.600 T:1925182384   DEBUG: CActiveAE::ClearDiscardedBuffers - buffer pool deleted
21:31:49.600 T:1925182384   DEBUG: Previous line repeats 1 times.
21:31:49.601 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] Using fltp internally between filters
21:31:49.656 T:1629463472   DEBUG: EPG - UpdateFromScraper - updating EPG for channel 'Channel 2' from client '453935575'
21:31:49.656 T:1629463472    INFO: easy_aquire - Created session to http://epg.example.com
21:31:51.479 T:1629463472   DEBUG: CFileCache::Open - opening <> using cache
21:31:51.479 T:1629463472   DEBUG: CurlFile::Open(0x57680098) http://epg.example.com/
21:31:53.748 T:1629463472   DEBUG: CCurlFile::Open - effective URL: <https://epg.example.com/guide.xml>
21:31:53.748 T:1367339952   DEBUG: Thread FileCache start, auto delete: false
21:31:54.680 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] Using fltp internally between filters
21:31:56.070 T:1367339952    INFO: CFileCache::Process - Source read didn't return any data! Hit eof(?)
21:31:56.120 T:1367339952   DEBUG: Thread FileCache 1367339952 terminating
21:31:56.950 T:1629463472  NOTICE: AddOnLog: PVR IPTV Simple Client: EPG Loaded.
21:31:56.953 T:1629463472   DEBUG: EPG - UpdateFromScraper - updating EPG for channel 'Channel 1' from client '453935575'
(Repeats lot of times for different channels)
21:31:56.968 T:1612686256   DEBUG: CPVRTimers - Update - updating timers
21:31:59.776 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] Using fltp internally between filters
21:31:59.851 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] Matrix coefficients:
21:31:59.851 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] FL: FC:0.707107
21:31:59.851 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] FR: FC:0.707107
21:32:04.872 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] Using fltp internally between filters
21:32:10.039 T:1925182384   DEBUG: Previous line repeats 1 times.
21:32:10.041 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] Matrix coefficients:
21:32:10.041 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] FL: FC:0.707107
21:32:10.041 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] FR: FC:0.707107
21:32:15.112 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] Using fltp internally between filters
21:32:15.114 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] Matrix coefficients:
21:32:15.114 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] FL: FC:0.707107
21:32:15.114 T:1925182384   DEBUG: ffmpeg[72BFF3B0]: [SWR] FR: FC:0.707107
21:32:49.701 T:1914696624   DEBUG: CAESinkPi:Drain delay:99ms now:0ms
21:32:59.702 T:1914696624   DEBUG: CAESinkPi:Deinitialize
21:32:59.703 T:1914696624   DEBUG: CAESinkPi:SetAudioProps hdmi_stream_channels 0 hdmi_channel_map 00000000
21:32:59.714 T:1914696624   DEBUG: COMXCoreComponent::Deinitialize : OMX.broadcom.audio_render handle 0x7237b5d0

And there's nothing else that could point to that. It's a 170MB log file full of ffmpeg DEBUG. no other relevant errors reported.

Any ideas ?
(This post was last modified: 2017-07-13 22:36 by KlotX.)
find quote
popcornmix Offline
Team-Kodi Member
Posts: 7,922
Joined: Feb 2011
Reputation: 331
Post: #10
(2017-07-13 22:35)KlotX Wrote:  And there's nothing else that could point to that. It's a 170MB log file full of ffmpeg DEBUG. no other relevant errors reported.

Any ideas ?

Upload the log file somewhere (google drive and dropbox are good for large files).
The snippets you post don't have any relevant information in.
find quote
KlotX Offline
Member
Posts: 87
Joined: Dec 2016
Reputation: 4
Post: #11
Hi.

I don't know what else to do. The large file had nothing else interesting and different from what I posted. If there anything specific I should search for? In this case the hanging doesn't happen when debug is active for video player. Any suggestions to get more info?

What about the crash log I posted before? Does it help in anyway?




Sent from my iPhone (typie typie)
find quote
popcornmix Offline
Team-Kodi Member
Posts: 7,922
Joined: Feb 2011
Reputation: 331
Post: #12
(2017-07-14 13:59)KlotX Wrote:  What about the crash log I posted before? Does it help in anyway?

I don't see the line "ERROR: CMMALVideo::dec_control_port_cb Error (status=3 EINVAL)" in the log you have posted.
That is the surprising error that I'd like to see if any preceding debug messages give any clues about why it failed (e.g. unusual resolution or format).
find quote
KlotX Offline
Member
Posts: 87
Joined: Dec 2016
Reputation: 4
Post: #13
Ok, so it seems that the first crash is unrelated.

Regarding that ERROR, the hang happened again, it's 6MB of logs, I'm going to redact the URLs and will send it to you, but there isn't anything special in there

I have a suspicion that it might be related with some badly formed PNG files or with failing to retrieve the EPG, but why it doesn't happen when the debug for VideoPlayer is active is a mystery to me.

Is there anything component I should enable its debug to check if I can make it hangs again ?
(This post was last modified: 2017-07-14 19:41 by KlotX.)
find quote
popcornmix Offline
Team-Kodi Member
Posts: 7,922
Joined: Feb 2011
Reputation: 331
Post: #14
(2017-07-14 19:41)KlotX Wrote:  Is there anything component I should enable its debug to check if I can make it hangs again ?

Video is most useful (but does generate a lot of logging).
I'd leave ffmpeg disabled for now - that is less likely to be useful.
find quote
KlotX Offline
Member
Posts: 87
Joined: Dec 2016
Reputation: 4
Post: #15
(2017-07-14 20:06)popcornmix Wrote:  
(2017-07-14 19:41)KlotX Wrote:  Is there anything component I should enable its debug to check if I can make it hangs again ?

Video is most useful (but does generate a lot of logging).
I'd leave ffmpeg disabled for now - that is less likely to be useful.

The past week I've only had Video enabled for debugging and I had no hangs whatsoever, as soon as I disabled it and enabled ffmpeg only, then it started crashing.

Maybe there's actually a race condition in the Video code that Debug makes it go away.. but I'll try again enabling Video Player debug.

Thanks.
find quote
Post Reply