Messages

Switched back to libcec 1.8.1-1 just to make sure using a later version wasn't the cause. It still does not work as intended but the behaviour changed slightly. The biggest difference is that with libcec 1.8.1-1 the tv does not switch on after the first power off. I won't use libcec 2.1.0-1 any more unless instructed to do so.

I will describe the existing behaviour first before commenting on the results of the suggested changers 1) 2) and 3).

With the TV in standby and starting vompclient it will wake tv and give picture. When the power button is pressed to TV goes into standby as expected. But when its turned on from standby there is no picture. Its possible to get picture back by switching to a NON hdmi input source and then back to the pi hdmi input source. When switching to the non hdmi input source one can observer the following message in the log:
21:25:40.694667 [debug]  3239 Remote - CECSourceActivated: 1 0
There is no such message when switching to other hdmi sources (unconnected).

Results of the suggested testing:
1) If the lines in changePowerState are uncommented.
With TV in standby and starting vompclient it will wake tv and give picture. If put to standby it will turn off and when awakened it will give picture. Note however that the remote commands won't be routed to vompclient. To get the remote functional one have to switch to another input source and back. Any input source could be chosen even the current that the pi is connected to!

2) Uncommenting the CEC_OPCODE_STANDBY
Exactly the same behaviour as observed making the changes in 1).

Have not had the time to check to other suggested combination of CEC_OPCODE_DECK_CONTROL and CEC_OPCODE_PLAY since it appears as if CEC_OPCODE_STANDBY is the offender!

3) If the call to incommingPowerkey is commented out it is not possible to get picture back by switching to another source and then back to the pi connected hdmi input not even if switching to a non hdmi input. Vompclient need to be restarted in order to get in a picture showing state.

With commit 2f7b15598665aacde6010e91f858cdb4f078c764 "Improve cec handling in remote linux" powering off and on is borked.

With the offending commit the TV is turned off but when turned on again it will only display a blank/black picture. There is no way to get the picture back but restoring vompclient.

In head, e.g. commit 7abb2e355d86c592f14d998e47e3594cce0d8a1b, the behaviour is slightly different. When the TV is powered off it turns off for a few seconds but then turns on again but with a no signal picture. Switching to another input source than the pi is connected to and back does give the picture back.

It should be noted that I'm using libcec 2.1.0-1 and not 1.8.1-1 and that the backend is vompserver 0.4.0 so I have patched vdr.cc to be protocol compliant with the vompserver plugin.

What is the reason and rationale behind the cec changes introduced. Would make it easier to troubleshoot. The commit log "Improve cec handling in remote linux" is not so informative :-)

I can confirm a first chirp at 54s and a second at 1min12s in the recording provided by winschrott.

@winschrott - I have downloaded your recording but has not yet been able to test it. My dev rpi did not have the mpeg2 decoder license "installed". Will take a look at it tomorrow.

As reference I'm making available a short 130MB 720p recording that has a lot of audio chirps at the beginning. It still has problem with the latest vompclient-marten and 0-4-1-dev.

https://drive.google.com/file/d/0B4LQIJR9gOUmamc3TW14NVQ5UFk/edit?usp=sharing

It is still an issue to me. Did quite a lot of debugging last spring without any success. It was also a bit discouraging that I was the only one having the problem. About a month ago I even bought a second pi with 512MB RAM just to make sure it was not related to me having a 256MB model. Same thing with the new pi.

Still I have great hope that this problem will be solved. Especially since there actually appears to be others experiencing the glitch with the sound. Any chance you could make available a short snippet of a recording showing the problem?

Notice that you succeeded in retrieving the sources after I started responding but I will still post...

The available vomp git repositories can be discovered here:
git.vomp.tv
Martens repository is vompclient-marten.git

Simply follow the guide but instead of

Code Select Expand

git clone http://git.vomp.tv/vompclient.git
cd vompclient

do

Code Select Expand

git clone http://git.vomp.tv/vompclient-marten.git
cd vompclient-marten

Is the power cost that overwhelming for you that you cannot have the raspberry pi on 24/7. The cost for me in Sweden is dirt cheap to drive a raspberry.

Realise that the energy cost where I live is very low compared to other places round the world but compared to other energy thieves in an household I wouldn't even bother turning the raspberry off. The advantage of having a picture instantly when the tv is turned on is significantly more important in our household.

I just realized while looking at your implementation that the layer description sanity test is not correct.

Its the value of

Code Select Expand

(data[test+1]&0x06)>>1
that shall be checked if its zero. NOT the calculated layer variable :-)

Choosing the ac3 audio track makes the chirps go away but in that case there are libav ac3 errors in the log as well as occasional disturbances in the audio. Much less annoying than the audio chirps but still audible:

I will continue looking into the demuxer and audio parsing code. It annoys me a lot not finding the root of the problems I see.

Code Select Expand


01:52:36.962970 [debug]  2309 Audio - warning we only support 48 KHz sampling rate
    Last message repeated 1 times
[ac3 @ 0xc03340] invalid sample rate
01:52:41.043573 [debug]  2309 VDR - Sending KA packet
01:52:41.047933 [debug]  2309 VDR - Rxd correct KA reply
01:52:44.727333 [debug]  2309 Audio - warning we only support 48 KHz sampling rate
[ac3 @ 0xc03340] invalid bitstream id
01:52:47.037351 [debug]  2309 VDR - Sending KA packet
01:52:47.045016 [debug]  2309 VDR - Rxd correct KA reply
01:52:53.021903 [debug]  2309 VDR - Sending KA packet
01:52:53.024487 [debug]  2309 VDR - Rxd correct KA reply
01:52:59.047240 [debug]  2309 VDR - Sending KA packet
01:52:59.052316 [debug]  2309 VDR - Rxd correct KA reply
01:53:00.000099 [debug]  2309 Timers - Timer firing for client 0xc2407c ref 1
01:53:00.001678 [debug]  2309 Timers - Timer firing for client 0xc1ab94 ref 2
01:53:00.003375 [debug]  2309 Timers - sending timer to 0xc2407c with parameter 1
01:53:00.010658 [debug]  2309 Timers - sending timer to 0xc1ab94 with parameter 2
01:53:00.013072 [debug]  2309 VVideoLiveTV - Timer Call 2  start.
01:53:00.015855 [debug]  2309 Timers - Starting set timer 1
01:53:00.016964 [debug]  2309 VVideoLiveTV - Timer Call 2 end.
01:53:00.017663 [debug]  2309 Timers - timerEventFinished for 0xc1ab94
01:53:00.019067 [debug]  2309 Timers - timerEventFinished RESTART for 0xc1ab94
01:53:00.014019 [debug]  2309 Timers - Starting set timer 1
01:53:00.020865 [debug]  2309 BoxStack - Update called
01:53:00.021624 [debug]  2309 BoxStack - Locked for update
01:53:00.022474 [debug]  2309 BoxStack - Unlocked for update
01:53:00.023312 [debug]  2309 Timers - timerEventFinished for 0xc2407c
01:53:00.024435 [debug]  2309 Timers - timerEventFinished RESTART for 0xc2407c
01:53:05.006448 [debug]  2309 VDR - Sending KA packet
01:53:05.017063 [debug]  2309 VDR - Rxd correct KA reply
01:53:11.036978 [debug]  2309 VDR - Sending KA packet
01:53:11.042163 [debug]  2309 VDR - Rxd correct KA reply
[ac3 @ 0xc03340] frame CRC mismatch
01:53:15.819078 [debug]  2309 Audio - warning we only support 48 KHz sampling rate
[ac3 @ 0xc03340] Additional substreams not implemented. Update your Libav version to the newest one from Git. If the problem still occurs, it means that your file has a feature which has not been implemented.
[ac3 @ 0xc03340] If you want to help, upload a sample of this file to ftp://upload.libav.org/incoming/ and contact the libav-devel mailing list.
[ac3 @ 0xc03340] unsupported frame type : skipping frame
01:53:17.034369 [debug]  2309 VDR - Sending KA packet
01:53:17.039655 [debug]  2309 VDR - Rxd correct KA reply
01:53:23.030194 [debug]  2309 VDR - Sending KA packet
01:53:23.033451 [debug]  2309 VDR - Rxd correct KA reply
01:53:29.026229 [debug]  2309 VDR - Sending KA packet
01:53:29.031699 [debug]  2309 VDR - Rxd correct KA reply
01:53:35.024122 [debug]  2309 VDR - Sending KA packet
01:53:35.027782 [debug]  2309 VDR - Rxd correct KA reply
01:53:41.026716 [debug]  2309 VDR - Sending KA packet
01:53:41.031866 [debug]  2309 VDR - Rxd correct KA reply
01:53:47.034125 [debug]  2309 VDR - Sending KA packet
01:53:47.038614 [debug]  2309 VDR - Rxd correct KA reply
01:53:53.032517 [debug]  2309 VDR - Sending KA packet
01:53:53.036165 [debug]  2309 VDR - Rxd correct KA reply
01:53:54.520081 [debug]  2309 Audio - warning we only support 48 KHz sampling rate
[ac3 @ 0xc03340] invalid bitstream id
[ac3 @ 0xc03340] frame CRC mismatch
01:53:59.009119 [debug]  2309 VDR - Sending KA packet
01:53:59.014178 [debug]  2309 VDR - Rxd correct KA reply
01:53:59.402754 [debug]  2309 Audio - warning we only support 48 KHz sampling rate
[ac3 @ 0xc03340] incomplete frame
01:54:00.000155 [debug]  2309 Timers - Timer firing for client 0xc2407c ref 1


The implementation works as good as mine.

I still have annoying high frequency chirps once in a while but the client is now usable. There are no log entries indicating that buffers are full.

The specs of the channels are http://www.svt.se/omsvt/om-sandningarna/hdtv/expertinformation:
Video
H.264/AVC/MPEG-4 Part 10 with variable BitRate (VBR). Practically this means that the bitrate may vary between 4 and 16 Mbit/s.

Audio
Both stereo and 5.1 multichannel. The 5.1 sound is coded as Dolby Digital (AC3) @ 448 kbit/s. The stereo sound is coded as MPEG1-L2@256kbit/s

Attached is a patch that will check the mpeg audio header before attempting to parse it. I have kept the implementation simple since I assume it will be rewritten if added to the sources.

The header check is implemented in a helper function private to the class AudioOMX named checkMpAudioHeader

There is one check that is questionable and that is the check if the bitrate index is of type "free format". Since the current code does not appear to take the "free format" into account when the bitrate is calculated I chose to include it in the helper. Its questionable since a function named checkMpAudioHeader shall only check the header and not perform application logic. (In this case invalidating the header if the bitrate index is of type "free format".

With this change there are no more audio drops during live tv. There are however occasional audio "chirps" during both live and playback of recordings on the 720p channels.

When the "chirps" occur there are, with the patch applied, messages about various mpeg header inconsistencies as well as libav errors:
[mp3 @ 0x7ecb60] big_values too big
[mp3 @ 0x7ecb60] Error while decoding MPEG audio frame.

Since recordings play fine using other methods I must ask. Is the vompserver plugin modifying the stream before its sent in some way compared to e.g. the streamdev plugin? In other words. Is the problems I see perhaps on the server side and not on the client side.

Thanks. I have figured out the lsf variable as well especially why it was also set when an mpeg 2.5 frame was detected.

I still get some libav errors. On at least one of them the layer value was a reserved value (00). Checking the libav source code I noticed they perform a santiy check on the header not only checking if the framesync is correct but also checking the values of the layer, bitrate and frequency.

A comment of the method making the header check in libav says: "fast header check for resync".

Will test with such checks in place to see what happens.

Another discrepancy between the documentation I have found, http://mpgedit.org/mpgedit/mpeg_format/mpeghdr.htm#MPEG%20HEADER, and the libav implementation is how the frame size is calculated. According to the doc the frame size should be calculated the same for layer 2 and layer 3 messages but in the libav implementation they differ. The docs does however not claim to be accurate... Do you have a pointer to some other documentation on the the mpeg audio frame header.

I suspect that line 1583 in AudioOMX::AdvanceMpAudioSync (audioomx.cc) is parsing the layer description bits incorrectly.

Code Select Expand

1583                         int layer=4-(data[test+2]&0x03)>>1;

The layer is as far as I can tell it located in position bit 18 and 17 of the mpeg audio frame header e.g in data[test+1]. The layer would then be calculated as:

Code Select Expand

int layer = 4 - ( (data[test+1] & 0x06) >>1 );

Does this make sense or have I totally misunderstood how the parsing is done?

Am i correct in the understanding of the local variable mpeg2 that its actually a variable holding status if the frame is an mpeg version 2.5 audio frame or not.

But what is the lsf variable?

I believe Marten referred to this post:
http://forum.loggytronic.com/index.php?topic=692.0

As mentioned in the post - the changes are trivial. The error received while compiling give a very good hint of what needs to change in  remotelinux.cc and remotelinux.h.

I wiped out my working tree where I had implemented these changes so I can unfortunately not provide a patch.

So I uncommented the logs in AudioOMX::AdvanceMpAudioSync and can observe the following:

Whenever there is some libav error the logs look like below (greping only logs with text Audio)

15:00:01.116161 [debug]  5064 Audio - FRAME: 0 2 12 48000 0 256 768
15:00:01.118679 [debug]  5064 Audio - FRAME DIAG: ff fc c4
15:00:01.120568 [debug]  5064 Audio - FRAME: 0 2 12 48000 0 256 768
15:00:01.122935 [debug]  5064 Audio - FRAME DIAG: ff fc c4
15:00:01.248154 [debug]  5064 Audio - FRAME: 0 2 12 48000 0 256 768
15:00:01.248326 [debug]  5064 Audio - FRAME DIAG: ff fc c4
15:00:01.253840 [debug]  5064 Audio - FRAME: 0 1 10 48000 0 320 320
15:00:01.255390 [debug]  5064 Audio - FRAME DIAG: ff fa a5
    Last message repeated 2 times
[mp3 @ 0xd3bea0] incomplete frame
15:00:01.262895 [debug]  5064 Audio - FRAME: 0 1 10 48000 0 320 320
15:00:01.266083 [debug]  5064 Audio - FRAME DIAG: ff fa a5
15:00:01.269644 [debug]  5064 Audio - FRAME: 0 1 10 48000 0 320 320
15:00:01.271737 [debug]  5064 Audio - FRAME DIAG: ff fa a5
15:00:01.427507 [debug]  5064 Audio - FRAME: 0 1 10 48000 0 320 320
15:00:01.427676 [debug]  5064 Audio - FRAME DIAG: ff fa a5
15:00:01.428898 [debug]  5064 Audio - FRAME: 0 2 12 48000 0 256 768
15:00:01.429013 [debug]  5064 Audio - FRAME DIAG: ff fc c4
15:00:01.437340 [debug]  5064 Audio - FRAME: 0 2 12 48000 0 256 768
15:00:01.438675 [debug]  5064 Audio - FRAME DIAG: ff fc c4
15:00:01.444627 [debug]  5064 Audio - FRAME: 0 2 12 48000 0 256 768
15:00:01.446386 [debug]  5064 Audio - FRAME DIAG: ff fc c4
15:00:01.451323 [debug]  5064 Audio - FRAME: 0 2 12 48000 0 256 768
15:00:01.454851 [debug]  5064 Audio - FRAME DIAG: ff fc c4
15:00:01.457935 [debug]  5064 Audio - FRAME: 0 2 12 48000 0 256 768
15:00:01.466471 [debug]  5064 Audio - FRAME DIAG: ff fc c4

Is this an indication of something broken in the stream or in the frame detection algorithms?

As for the longer audio drops there were at least a few where the FRAME message did not change - nor where there any libav errors.

Since the last post I have tested various buffer settings without any improvements. Since playback is fine with omxplayer and omxplayer is using ffmpeg and not libav I spent some time compiling ffmpeg and compiled a vompclient version using ffmpeg instead of libav. Did not improve anything.

Is there a way to dump the stream, by modifying source code on the client and/or server side, to a file to check if the problem is with the streamed data? Suggestions on where and how this could be done would be appreciated.