Audio sync issue - Nebula / Jet Lag the Game

Help and Support Vero 4K / Vero 4K +
1

I’m experiencing some issues with audio sync when watching “Jet Lag: the Game” on Nebula using the slyguy Nebula addon on my Vero 4K+.

I previously opened an issue with the addon developer, but after some investigation we have determined that the issue is not with the addon, and is likely with OSMC and/or the Vero 4K+.

Expected behaviour:

  • Install the slyguy Nebula addon
  • Using the addon, sign in to Nebula
  • Navigate to a Jet Lag video
  • Play the video
  • Audio should be in sync with the video

Actual behaviour:

  • Audio is several seconds ahead of the video

Episode 2 of the Japan season (the latest episode as of the time of submission of this issue) is a good example. It begins with an extended motion-graphics sequence, and the sound effects that play in time with the graphics on desktop play several seconds ahead on Kodi.

Adjusting the audio offset in Kodi makes no difference: the audio plays several seconds ahead of the video, regardless of how the audio offset is set.

So far it appears to only be Jet Lag that is affected. None of the other creators that I watch have the same issue, including the other channels by the same creator (Wendover Productions, Half as Interesting).

The same video plays with the correct audio offset in a web browser, and the YouTube version of Jet Lag plays with the correct audio offset in Kodi.

Previous seasons were not affected by this issue when I watched them at the time of release, but I also tested some previous episodes today and found the same issue.

I’ve tested this with three versions of the addon (0.2.3, 0.2.4, and the latest 0.2.5) and get the same behaviour in each case. I’m running the latest available version of OSMC.

I’ve also tested this on Kodi on my Ubuntu desktop, and the addon developer has tested on his Windows machine, and in neither case can we reproduce the issue. It’s only on my OSMC Vero 4K+ that I’ve been able to reproduce the issue.

Here is a log extract from playing a video:

2023-06-07 16:40:26.171 T:3153  warning <general>: Setting most video properties through ListItem.setInfo() is deprecated and might be removed in future Kodi versions. Please use the respective setter in InfoTagVideo.
2023-06-07 16:40:26.222 T:2952     info <general>: VideoPlayer::OpenFile: plugin://slyguy.nebula/?_=play&_play=1&slug=jetlag-ep-2-we-played-a-96hour-game-of-capture-the-flag-across-japan
2023-06-07 16:40:26.230 T:3300     info <general>: Creating InputStream
2023-06-07 16:40:26.394 T:3300     info <general>: AddOnLog: inputstream.adaptive: [Repr. chooser] Resolution set: 1920x1080, max allowed: 1920x1080, Adjust refresh rate: 0
2023-06-07 16:40:26.584 T:3300     info <general>: AddOnLog: inputstream.adaptive: Successfully parsed manifest file (Periods: 1, Streams in first period: 3, Type: live)
2023-06-07 16:40:26.584 T:3300     info <general>: Creating Demuxer
2023-06-07 16:40:26.587 T:3300     info <general>: Opening stream: 1001 source: 256
2023-06-07 16:40:26.687 T:3300     info <general>: Creating video codec with codec id: 27
2023-06-07 16:40:26.688 T:3300     info <general>: CDVDVideoCodecAmlogic: using Amlogic decoder H.264/MVC
2023-06-07 16:40:26.722 T:3300     info <general>: secureOSMC setup successful
2023-06-07 16:40:26.723 T:3300     info <general>: auth_get_key_id: TEEC_InvokeCommand failed with code 0xffff0006 origin 0x4
2023-06-07 16:40:26.723 T:3300  warning <general>: OSMCSecureOS::getKeyId: unable to get key id
2023-06-07 16:40:26.723 T:3300  warning <general>: OSMCSecureOS: key-id = <unknown>
2023-06-07 16:40:26.726 T:3300     info <general>: DVDVideoCodecAmlogic: Opened Amlogic Codec
2023-06-07 16:40:26.726 T:3300     info <general>: Creating video thread
2023-06-07 16:40:26.727 T:3300     info <general>: Opening stream: 1002 source: 256
2023-06-07 16:40:26.729 T:3306     info <general>: running thread: video_thread
2023-06-07 16:40:26.835 T:3300     info <general>: Finding audio codec for: 86018
2023-06-07 16:40:26.842 T:3300     info <general>: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2023-06-07 16:40:26.842 T:3300     info <general>: OpenStream: Allowing max Out-Of-Sync Value of 10 ms
2023-06-07 16:40:26.842 T:3300     info <general>: Creating audio thread
2023-06-07 16:40:26.842 T:3300     info <general>: Opening stream: 1003 source: 256
2023-06-07 16:40:26.845 T:3310     info <general>: running thread: CVideoPlayerAudio::Process()
2023-06-07 16:40:26.882 T:3300     info <general>: CDVDSubtitlesLibass: Using libass version 1500000
2023-06-07 16:40:26.882 T:3300     info <general>: CDVDSubtitlesLibass: Creating ASS library structure
2023-06-07 16:40:26.882 T:3300     info <general>: CDVDSubtitlesLibass: Initializing ASS Renderer
2023-06-07 16:40:26.884 T:3300     info <general>: CDVDSubtitlesLibass: Initializing ASS library font settings
2023-06-07 16:40:26.962 T:3300     info <general>: CDVDSubtitlesLibass: Creating new ASS track
2023-06-07 16:40:27.326 T:3306     info <general>: CBitstreamConverter::Open bitstream to annexb init
2023-06-07 16:40:27.346 T:3310     info <general>: CDVDAudioCodecFFmpeg::Open() Successful opened audio decoder aac
2023-06-07 16:40:27.347 T:3310     info <general>: Creating audio stream (codec id: 86018, channels: 2, sample rate: 48000, no pass-through)
2023-06-07 16:40:27.357 T:3047     info <general>: CActiveAESink::OpenSink - initialize sink
2023-06-07 16:40:27.357 T:3047     info <general>: CAESinkALSA::Initialize - Requested layout FL, FR
2023-06-07 16:40:27.358 T:3047     info <general>: CAESinkALSA::Initialize - set digital codec 0
2023-06-07 16:40:27.358 T:3047     info <general>: CAESinkALSA::Initialize - Attempting to open device "default"
2023-06-07 16:40:27.367 T:3047     info <general>: CAESinkALSA::Initialize - Opened device "default"
2023-06-07 16:40:27.367 T:3047     info <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2023-06-07 16:40:27.367 T:3047     info <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE4
2023-06-07 16:40:27.369 T:3047     info <general>: CAESinkALSA::Initialize - speaker layout 0
2023-06-07 16:40:27.388 T:3047    error <general>: CAESinkALSA - snd_pcm_writei(-32) Broken pipe - trying to recover
2023-06-07 16:40:27.887 T:2952     info <general>: Loading skin file: VideoFullScreen.xml, load type: KEEP_IN_MEMORY
2023-06-07 16:40:27.897 T:2952     info <general>: Constructing CRendererAML
2023-06-07 16:40:29.142 T:2952     info <general>: CVideoPlayer::CloseFile()
2023-06-07 16:40:29.142 T:2952     info <general>: VideoPlayer: waiting for threads to exit
2023-06-07 16:40:29.143 T:3300     info <general>: CVideoPlayer::OnExit()
2023-06-07 16:40:29.143 T:3300     info <general>: Closing stream player 1
2023-06-07 16:40:29.145 T:3300     info <general>: Waiting for audio thread to exit
2023-06-07 16:40:29.150 T:3310     info <general>: thread end: CVideoPlayerAudio::OnExit()
2023-06-07 16:40:29.151 T:3300     info <general>: Closing audio device
2023-06-07 16:40:29.171 T:3047     info <general>: CActiveAESink::OpenSink - initialize sink
2023-06-07 16:40:29.171 T:3300     info <general>: Deleting audio codec
2023-06-07 16:40:29.172 T:3300     info <general>: Closing stream player 2
2023-06-07 16:40:29.173 T:3300     info <general>: waiting for video thread to exit
2023-06-07 16:40:29.185 T:3306     info <general>: thread end: video_thread
2023-06-07 16:40:29.187 T:3300     info <general>: deleting video codec
2023-06-07 16:40:29.192 T:3300     info <general>: Closing stream player 3
2023-06-07 16:40:29.207 T:3069     info <general>: Deleting settings information for files plugin://slyguy.nebula/?_=play&_play=1&slug=jetlag-ep-2-we-played-a-96hour-game-of-capture-the-flag-across-japan
2023-06-07 16:40:29.214 T:3300     info <general>: ADDON: Dll Destroyed - InputStream Adaptive
2023-06-07 16:40:29.216 T:2952     info <general>: VideoPlayer: finished waiting
2023-06-07 16:40:29.216 T:2952     info <general>: CVideoPlayer::CloseFile()
2023-06-07 16:40:29.216 T:2952     info <general>: VideoPlayer: waiting for threads to exit
2023-06-07 16:40:29.216 T:2952     info <general>: VideoPlayer: finished waiting
2023-06-07 16:40:29.273 T:2952    error <general>: Control 55 in window 10025 has been asked to focus, but it can't
2023-06-07 16:40:29.369 T:3047     info <general>: CAESinkALSA::Initialize - Requested layout FL, FR
2023-06-07 16:40:29.369 T:3047     info <general>: CAESinkALSA::Initialize - set digital codec 0
2023-06-07 16:40:29.370 T:3047     info <general>: CAESinkALSA::Initialize - Attempting to open device "default"
2023-06-07 16:40:29.376 T:3047     info <general>: CAESinkALSA::Initialize - Opened device "default"
2023-06-07 16:40:29.377 T:3047     info <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2023-06-07 16:40:29.377 T:3047     info <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE4
2023-06-07 16:40:29.386 T:3047     info <general>: CAESinkALSA::Initialize - speaker layout 0
2023-06-07 16:40:30.047 T:3153  warning <general>: Setting most video properties through ListItem.setInfo() is deprecated and might be removed in future Kodi versions. Please use the respective setter in InfoTagVideo.

The addon developer suggested that the issue might be related to the message “Your hardware does not support AE_FMT_FLOAT, trying other formats”, and linked to the following issue from a different project that appears to be similar: RPi4 (Bullseye update) Kodi error: "Your hardware does not support AE_FMT_FLOAT" · Issue #4998 · MichaIng/DietPi · GitHub

Please let me know if there’s anything I can do about this issue, or if there’s anything I can do to help you investigate it further. Thanks!

2

Without full logs and debugging enabled, it’s hard to say. You also haven’t described your audio set up at all, which doesn’t give us much to go on.

3

To get a better understanding of the problem you are experiencing we need more information from you. The best way to get this information is for you to upload logs that demonstrate your problem. You can learn more about how to submit a useful support request here.

Depending on the used skin you have to set the settings-level to standard or higher, in summary:

  • enable debug logging at settings->system->logging

  • reboot the OSMC device twice(!)

  • reproduce the issue

  • upload the log set (all configs and logs!) either using the Log Uploader method within the My OSMC menu in the GUI or the ssh method invoking command grab-logs -A

  • publish the provided URL from the log set upload, here

Thanks for your understanding. We hope that we can help you get up and running again shortly.

OSMC skin screenshot:

image
image960×539 41.4 KB

4

Thanks for the information on how to collect and upload the debug logs. They’re now available here: https://paste.osmc.tv/owajufixuz

My audio setup is simply that the Vero 4K+ is connected to my TV via HDMI. Audio plays through the TV’s speakers.

5

Could you first set “Adjust display refresh rate” to “always” or “on start/stop” at settings → player → videos? Please, don’t activate “sync playback to display”.
Try again and provide logs again in case nothing changed.

8 
2023-06-08 14:46:16.429 T:3065     info <general>: CAESinkALSA::InitializeHW - Your hardware does not support AE_FMT_FLOAT, trying other formats
2023-06-08 14:46:16.429 T:3065     info <general>: CAESinkALSA::InitializeHW - Using data format AE_FMT_S24NE4

This isn’t an issue – assuming you can hear sound.

The problem is this, which is occurring very frequently

2023-06-08 14:46:16.299 T:3639    debug <general>: CVideoPlayerVideo - video decoder returned error

If it can be reproduced with a recording we can look in to it further

11

@JimKnopf extracted the stream and it appears the stream has a variable refresh rate. This will cause issues with hardware accelerated playback.

As the video is low bitrate and low resolution, you should be able to get away with changing H264 acceleration to HD and up in Settings.

12

This seems to have fixed it thanks. Although, my TV blanks the display for several seconds when switching refresh rate, so it’s a bit annoying. However, I then tried setting the display refresh rate to 60 and disabling the adjustment, and the video played with correct audio sync and it didn’t seem to cause any obvious audio sync problems with the few 50 fps videos I tried. So I think I’ll leave it on that setting for now and see if I spot any issues going forward - I can always re-enable “adjust display refresh rate” if necessary.

This didn’t seem to make any difference either way.

I’m still seeing this error in the log, even though the video is playing correctly now. If you think it’s worth looking into further, I’m happy to help out with whatever you need to investigate it, but I’ll leave it up to you to decide on that, as the video is now playing correctly for me.

Here’s the debug log with the refresh rate set to 60 and the video playing with correct audio sync: https://paste.osmc.tv/femudogebi

Thank you for your help!