Vero 4k Crash

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

Just got my first Crash. I started a movie and after a couple of minutes the screen went black, no audio and system unresponsive.
I logged in through ssh, tried grab-logs -A but it didn’t work, I waited for quite a while but the command didn’t complete.
I copied the kodi log and tried to reboot from command line (sudo reboot), but that too didn’t work. I had to unplug the power to get back up and running.
I upload the log at: http://paste.osmc.tv/jorexodohe.vhdl
the crash portion of it is here (movie starts at 15:46, and crashes at 15:48). Hopefully there’s some useful information.

15:46:10.429 T:4077691472  NOTICE: VideoPlayer: Opening: /mnt/Storage_Pool/Media/Cartoni Bimbi/Toy Story 3/Toy Story 3.mkv
15:46:10.429 T:4077691472 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
15:46:10.430 T:3102733056  NOTICE: Creating InputStream
15:46:10.498 T:3102733056  NOTICE: Creating Demuxer
15:46:11.151 T:3102733056  NOTICE: Opening stream: 0 source: 256
15:46:11.151 T:3102733056  NOTICE: Creating video codec with codec id: 28
15:46:11.153 T:3102733056   ERROR: Unable to load libamplayer.so, reason: libamplayer.so: cannot open shared object file: No such file or directory
15:46:11.153 T:3102733056 WARNING: CAMLCodec::CAMLCodec libamplayer.so not found, trying libamcodec.so instead
15:46:11.162 T:3102733056  NOTICE: Creating video thread
15:46:11.163 T:2807034624  NOTICE: running thread: video_thread
15:46:11.163 T:3102733056  NOTICE: Opening stream: 1 source: 256
15:46:11.163 T:3102733056  NOTICE: Finding audio codec for: 86020
15:46:11.163 T:3102733056  NOTICE: Creating audio thread
15:46:11.163 T:2837443328  NOTICE: running thread: CVideoPlayerAudio::Process()
15:46:11.163 T:3102733056  NOTICE: Opening stream: 8 source: 256
15:46:11.175 T:2837443328  NOTICE: Creating audio stream (codec id: 86020, channels: 8, sample rate: 48000, pass-through)
15:46:11.211 T:2807034624  NOTICE: CAMLCodec::OpenDecoder - using V4L2 pts format: 64Bit
15:46:11.584 T:4077691472  NOTICE: Display resolution ADJUST : 1920x1080 @ 23.98 - Full Screen (27) (weight: 0.000)
15:46:11.768 T:4077691472  NOTICE: VideoPlayer: OnLostDisplay received
15:46:12.035 T:2807034624 WARNING: CRenderManager::WaitForBuffer - timeout waiting for buffer
15:46:12.507 T:2823811840   ERROR: CCurlFile::FillBuffer - Failed: HTTP returned error 500
15:46:12.507 T:2823811840   ERROR: CCurlFile::Open failed with code 500 for https://assets.fanart.tv/fanart/movies/15655/movielogo/the-tigger-movie-51bd7631bd1f2.png
15:46:14.607 T:4077691472  NOTICE: VideoPlayer: OnResetDisplay received
15:46:32.338 T:3361682176   ERROR: $$$ [kodi.callbacks] - ERROR encountered for Task T1, Event onPlayBackStarted
                                        ERROR mesage: Requests Timeout Error: HTTPConnectionPool(host='192.168.1.144', port=5000): Read timed out. (read timeout=20)
15:46:41.334 T:2788446976   ERROR: CCurlFile::FillBuffer - Failed: Timeout was reached(28)
15:46:41.334 T:2788446976   ERROR: CCurlFile::Open failed with code 0 for https://assets.fanart.tv/fanart/movies/2062/hdmovielogo/ratatouille-5148dd29db1e2.png
15:47:10.290 T:4077691472  NOTICE: Samba is idle. Closing the remaining connections
15:48:37.392 T:2837443328  NOTICE: CVideoPlayerAudio::Process - stream stalled
15:48:45.777 T:3102733056  NOTICE: CVideoPlayer::OnExit()
15:48:45.777 T:3102733056  NOTICE: VideoPlayer: eof, waiting for queues to empty
15:48:45.777 T:3102733056  NOTICE: Closing stream player 1
15:48:45.777 T:3102733056  NOTICE: CDVDMessageQueue(audio)::WaitUntilEmpty
15:48:45.777 T:3102733056  NOTICE: Waiting for audio thread to exit
15:48:45.777 T:2837443328   ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true
15:48:45.777 T:2837443328  NOTICE: thread end: CVideoPlayerAudio::OnExit()
15:48:45.777 T:3102733056  NOTICE: Closing audio device
15:48:45.778 T:3102733056  NOTICE: Deleting audio codec
15:48:45.778 T:3102733056  NOTICE: Closing stream player 2
15:48:45.778 T:3102733056  NOTICE: CDVDMessageQueue(video)::WaitUntilEmpty
15:48:45.789 T:3102733056  NOTICE: waiting for video thread to exit
15:48:45.789 T:2807034624   ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true
15:48:45.789 T:2807034624  NOTICE: thread end: video_thread
15:48:45.789 T:3102733056  NOTICE: deleting video codec
15:48:45.847 T:3102733056  NOTICE: Closing stream player 3
2

Unfortunately that’s not a debug log, so it’s hard to see what the issue is. The log only shows an issue connecting to Fanart.tv (they might be experiencing some problems).

When you say grab-logs -A didn’t work, what happened? If you were able to login via SSH, then the system is indeed responsive.

Let us know if it happens again

Sam

3

When I tried to do grab-logs -A, I waited for a couple of minutes but the command didn’t complete (no prompt) and I had to do a CTRL-C. I then did a sudo reboot, but the system didn’t reboot.
I’ll let you know if that happens again. Any other files should I copy, next time?

4

Next time check the output of dmesg. Hopefully this won’t happen again.

Sam

5

Happened again, 5 minutes into a movie. Last few lines of the log:

18:07:31.497 T:2794029824  NOTICE: CVideoPlayerAudio::Process - stream stalled
18:07:42.692 T:2694415104  NOTICE: CVideoPlayer::OnExit()
18:07:42.693 T:2694415104  NOTICE: VideoPlayer: eof, waiting for queues to empty
18:07:42.693 T:2694415104  NOTICE: Closing stream player 1
18:07:42.693 T:2694415104  NOTICE: CDVDMessageQueue(audio)::WaitUntilEmpty
18:07:42.693 T:2694415104  NOTICE: Waiting for audio thread to exit
18:07:42.693 T:2794029824   ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true
18:07:42.693 T:2794029824  NOTICE: thread end: CVideoPlayerAudio::OnExit()
18:07:42.693 T:2694415104  NOTICE: Closing audio device
18:07:42.694 T:2694415104  NOTICE: Deleting audio codec
18:07:42.694 T:2694415104  NOTICE: Closing stream player 2
18:07:42.694 T:2694415104  NOTICE: CDVDMessageQueue(video)::WaitUntilEmpty
18:07:42.704 T:2694415104  NOTICE: waiting for video thread to exit
18:07:42.704 T:2869527296   ERROR: Got MSGQ_ABORT or MSGO_IS_ERROR return true
18:07:42.704 T:2869527296  NOTICE: thread end: video_thread
18:07:42.704 T:2694415104  NOTICE: deleting video codec
18:07:42.778 T:2694415104  NOTICE: Closing stream player 3
18:08:27.259 T:2794029824   ERROR: CCurlFile::Stat - Failed: Timeout was reached(28) for https://assets.fanart.tv/fanart/movies/12105/moviedisc/yellow-submarine-51feeaaa12e2c.png
18:09:22.599 T:3684500224  NOTICE: ES: Client  from ::ffff:192.168.1.3 timed out
18:10:31.797 T:4075336272  NOTICE: CVideoPlayer::CloseFile()
18:10:31.797 T:4075336272  NOTICE: VideoPlayer: waiting for threads to exit

Last few lines of dmesg:

[90494.603327] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1)
[90494.603332] aml_spdif_dai: share the same clock
[90494.603339] aml_audio_hw: IEC958 PCM32
[90494.603366] hdmitx: audio: aout notify rate 48000
[90494.603368] hdmitx: audio: aout notify size 32
[90494.603370] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[90494.603372] hdmitx: audio: no update
[90494.603382] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[90494.603718] sysfs set hdmi_ch to 0
[90494.603718] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1)
[90494.603722] aml_spdif_dai: share the same clock
[90494.603729] aml_audio_hw: IEC958 PCM32
[90494.603735] hdmitx: audio: aout notify rate 48000
[90494.603737] hdmitx: audio: aout notify size 32
[90494.603739] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[90494.603740] hdmitx: audio: no update
[90494.603750] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[90494.604634] channel count should be 8, we got 2 aborting
[90494.605429] aml_snd_m8_card aml_m8_snd.46: I2S playback enable
[90494.605435] aml_snd_m8_card aml_m8_snd.46: IEC958 playback enable
[90494.664762] vpts to scr, apts = 0x0, vpts = 0x10486325
[90494.664790] codec:[video4osd] first  picture {1280,720} pts:10486325,
[90494.664817] codec:new toggle keep_id
[90494.706548] codec:VsyncEnableVideoLayer
[90494.967063] codec:finished correct frame dur
[90494.967063] codec: new=4004,old_duration=4004,cnt=25
[90500.108416] aml_snd_m8_card aml_m8_snd.46: I2S playback disable
[90500.108431] aml_snd_m8_card aml_m8_snd.46: IEC958 playback disable
[90500.108492] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1)
[90500.108499] aml_spdif_dai: share the same clock
[90500.108507] aml_audio_hw: IEC958 PCM32
[90500.108513] hdmitx: audio: aout notify rate 48000
[90500.108517] hdmitx: audio: aout notify size 32
[90500.108521] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[90500.108525] hdmitx: audio: no update
[90500.108530] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[90500.389366] codec:video_blackout_policy_store(0)
[90500.389425] [tsync_avevent]event:1, param 1
[90500.389430] video pause!
[90500.393988] DI: di_receiver_event_fun , is_bypass() 1 trick_mode 0 bypass_all 0
[90500.394001] di_receiver_event_fun: vf_notify_receiver unreg
[90500.394026] DI: di_unreg_process unreg start 1.
[90500.394045] codec_mm:NULL mem_handle for keeper!!
[90500.394053] codec:vf_keep_current keep_y_addr=0000000067c00000 64e66800
[90500.394059] codec:ge2d_store_frame_NV21 cur_index:s:0x121110
[90500.394069] codec:ge2d_store_frame d:0xd9d8
[90500.397580] codec:vf_keep_current: VIDTYPE_VIU_NV21
[90500.397582] codec:vf_keep_current: keep video on with keep
[90500.397587] [tsync_avevent]event:2, param 0
[90500.397590] codec:video first pts = 0
[90500.397600] DI: di_unreg_process vf unreg cost 0 ms.
[90500.397601] DI: di_unreg_process unreg stop 0.
[90500.404090] codec:vdec1 video changed to 0 x 0 0 fps clk->200MHZ
[90500.404354] codec:vdec_create instance ffffff800471a000, total 1
[90500.404390] codec:Video stbuf alloced at 0000000063b00000, size = 10485760
[90500.404400] codec:vdec_init, dev_name:amvdec_h264, vdec_type=VDEC_TYPE_SINGLE
[90500.404402] codec:vdec_init set vfm decoder ffffff800471a000
[90500.404404] codec:vdec_dev_reg.mem[0x64500000 -- 0x674fffff]
[90500.406787] codec:H264 sysinfo: 1280x720 duration=4004, pts_outside=1, 
[90500.406787] codec:vdec_request_irq ffffffc0016d32d0, vh264-irq
[90500.406806] DI: di_receiver_event_fun: vframe provider reg
[90500.416853] set run_early_proc_fun_flag to 1
[90500.417008] codec:vdec_init, vf_provider_name = 
[90500.417601] codec:video first pts = 0
[90500.417605] codec:vdec_request_irq ffffffc0016c4740, parser
[90500.418338] codec:video_blackout_policy_store(1)
[90500.449531] codec:video first checkin pts = 13884a05
[90500.449533] codec:first check in vpts <0x25:0x13884a05> ok!
[90500.449965] codec:Enter set parameter cmd1.
[90500.450006] codec:vdec1 video changed to 3840 x 2160 60 fps clk->667MHZ
[90500.450012] codec:actual_dpb_size 24 max_dpb_size 3
[90500.450096] codec:video first pts = 13884a05
[90500.473865] pre_de_buf_config: source change: 0x0/0/0/0=>0x9000/1280/720/0
[90500.473872] DI:7920 disable post.
[90500.529630] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1)
[90500.529634] aml_spdif_dai: share the same clock
[90500.529640] aml_audio_hw: IEC958 PCM32
[90500.529644] hdmitx: audio: aout notify rate 48000
[90500.529646] hdmitx: audio: aout notify size 32
[90500.529648] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[90500.529649] hdmitx: audio: no update
[90500.529658] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[90500.529918] sysfs set hdmi_ch to 0
[90500.529918] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1)
[90500.529921] aml_spdif_dai: share the same clock
[90500.529927] aml_audio_hw: IEC958 PCM32
[90500.529931] hdmitx: audio: aout notify rate 48000
[90500.529933] hdmitx: audio: aout notify size 32
[90500.529935] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[90500.529935] hdmitx: audio: no update
[90500.529943] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[90500.530088] channel count should be 8, we got 2 aborting
[90500.530528] aml_snd_m8_card aml_m8_snd.46: I2S playback enable
[90500.530533] aml_snd_m8_card aml_m8_snd.46: IEC958 playback enable
[90500.587338] vpts to scr, apts = 0x0, vpts = 0x13884a05
[90500.587373] codec:[video4osd] first  picture {1280,720} pts:13884a05,
[90500.587401] codec:new toggle keep_id
[90500.629120] codec:VsyncEnableVideoLayer
[90500.926758] codec:finished correct frame dur
[90500.926759] codec: new=4004,old_duration=4004,cnt=25
[92339.301270] aml_snd_m8_card aml_m8_snd.46: I2S playback disable
[92339.301290] aml_snd_m8_card aml_m8_snd.46: IEC958 playback disable
[92339.301372] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1)
[92339.301380] aml_spdif_dai: share the same clock
[92339.301390] aml_audio_hw: IEC958 PCM32
[92339.301397] hdmitx: audio: aout notify rate 48000
[92339.301401] hdmitx: audio: aout notify size 32
[92339.301407] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[92339.301410] hdmitx: audio: no update
[92339.301416] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[93268.736172] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1)
[93268.736185] aml_spdif_dai: share the same clock
[93268.736194] aml_audio_hw: IEC958 PCM32
[93268.736200] hdmitx: audio: aout notify rate 48000
[93268.736203] hdmitx: audio: aout notify size 32
[93268.736208] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[93268.736211] hdmitx: audio: no update
[93268.736222] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[93268.736468] sysfs set hdmi_ch to 0
[93268.736517] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1)
[93268.736525] aml_spdif_dai: share the same clock
[93268.736533] aml_audio_hw: IEC958 PCM32
[93268.736539] hdmitx: audio: aout notify rate 48000
[93268.736543] hdmitx: audio: aout notify size 32
[93268.736547] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[93268.736550] hdmitx: audio: no update
[93268.736559] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[93268.736710] channel count should be 8, we got 2 aborting
[93268.737157] aml_snd_m8_card aml_m8_snd.46: I2S playback enable
[93268.737171] aml_snd_m8_card aml_m8_snd.46: IEC958 playback enable
[93774.679902] aml_snd_m8_card aml_m8_snd.46: I2S playback disable
[93774.679917] aml_snd_m8_card aml_m8_snd.46: IEC958 playback disable
[93774.679972] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(1)
[93774.679979] aml_spdif_dai: share the same clock
[93774.679987] aml_audio_hw: IEC958 PCM32
[93774.679993] hdmitx: audio: aout notify rate 48000
[93774.679997] hdmitx: audio: aout notify size 32
[93774.680002] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[93774.680005] hdmitx: audio: no update
[93774.680011] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[93774.689229] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=44100, runtime->channels=2, same source mode(1)
[93774.689240] aml_spdif_dai: share the same clock
[93774.689249] aml_audio_hw: IEC958 PCM32
[93774.689254] hdmitx: audio: aout notify rate 44100
[93774.689258] hdmitx: audio: aout notify size 32
[93774.689262] hdmitx: audio: aout notify sample rate 44100 was 48000
[93774.689267] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[93774.689282] hdmtix: setting audio 0
[93774.689292] hdmitx tx_aud_src = 0
[93774.689321] hdmitx: fs = 2, cd = 5, tmds_clk = 74176
[93774.689325] hdmitx aud_n_para = 17836
[93774.689345] hdmitx set channel status
[93774.689403] hdmitx: audio: Audio Output Channels set to: 2:1
[93774.689413] hdmitx: audio: set audio param
[93774.689424] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[93774.689629] sysfs set hdmi_ch to 0
[93774.689665] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=44100, runtime->channels=2, same source mode(1)
[93774.689670] aml_spdif_dai: share the same clock
[93774.689677] aml_audio_hw: IEC958 PCM32
[93774.689682] hdmitx: audio: aout notify rate 44100
[93774.689685] hdmitx: audio: aout notify size 32
[93774.689689] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[93774.689692] hdmitx: audio: no update
[93774.689698] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[93774.689802] channel count should be 8, we got 2 aborting
[93775.229239] codec:DisableVideoLayer()
[93775.242221] DI: di_receiver_event_fun , is_bypass() 1 trick_mode 0 bypass_all 0
[93775.242231] di_receiver_event_fun: vf_notify_receiver unreg
[93775.242246] DI: di_unreg_process unreg start 1.
[93775.242258] codec:DisableVideoLayer()
[93775.242262] codec:disbled keep video before free keep buffer.
[93775.242266] codec:disbled video for next before free keep buffer!
[93775.242270] codec:DisableVideoLayer()
[93775.242275] codec:free_alloced_keep_buffer 0000000067c00000.0000000067b00000.0000000068000000
[93775.242557] codec:free_alloced_keep_buffer           (null).          (null).          (null)
[93775.242566] [tsync_avevent]event:2, param 0
[93775.242573] codec:video first pts = 0
[93775.242584] DI: di_unreg_process vf unreg cost 0 ms.
[93775.242588] DI: di_unreg_process unreg stop 0.
[93775.252313] codec:vdec1 video changed to 0 x 0 0 fps clk->200MHZ
[93775.252500] codec:video_disable_store(1)
[93775.252510] codec:DisableVideoLayer()
[93775.252516] codec:free_alloced_keep_buffer           (null).          (null).          (null)
[93775.252549] vfm_map_store:rm default
[93775.252577] vfm_map_store:add default  decoder ppmgr deinterlace amlvideo amvideo
[93775.270402] codec:VsyncDisableVideoLayer
[93775.270413] codec:AFBC off now.
[93775.442403] vout_serve: vmode set to null
[93775.442432] vout_serve: disable HDMI PHY as soon as possible
[93775.442440] fb: current vmode=1080p24hz, cmd: 0x50000
[93775.442451] tv_vout: tv_set_current_vmode[919]fps_target_mode=59
[93775.442457] tv_vout: mode is 59,sync_duration_den=1,sync_duration_num=60
[93775.442468] tv_vout: 3Invalid video output modes.
[93775.442472] tv_vout: new mode =null set ok
[93775.442476] vout_serve: vinfo mode is: null
[93775.442479] vout_serve: new mode null set ok
[93775.442489] hdmitx: edid: not find mapped vic
[93775.442496] hdmitx: video: get current mode: null
[93775.442500] hdmitx: update physcial size: 1650 930
[93775.442504] hdmitx: video: null not valid hdmi mode
[93775.442525] fb: current vmode=null, cmd: 0x10000
[93775.479075] hdmitx: set frac_rate_policy as 0
[93775.479103] vout_serve: vmode set to 1080p60hz
[93775.479125] vout_serve: disable HDMI PHY as soon as possible
[93775.479131] fb: current vmode=null, cmd: 0x50000
[93775.479138] tv_vout: tv_set_current_vmode[919]fps_target_mode=16
[93775.479143] tv_vout: mode is 16,sync_duration_den=1,sync_duration_num=60
[93775.479154] tv_vout: TV mode 1080p60hz selected.
[93775.479158] 
               vdac_enable: on:0,module_sel:8
[93775.479169] 
               vdac_enable: on:0,module_sel:8
[93775.479177] tv_vout: new mode =1080p60hz set ok
[93775.479181] vout_serve: vinfo mode is: 1080p60hz
[93775.479185] vout_serve: new mode 1080p60hz set ok
[93775.479202] hdmitx: video: get current mode: 1080p60hz
[93775.479205] hdmitx: update rx hdr info 7
[93775.479209] hdmitx: update physcial size: 1650 930
[93775.479251] hdmitx: system: already init VIC = 0  Now VIC = 16
[93775.479256] hdmitx: rx has SCDC present indicator
[93775.481269] hdmirx version is 2.0
[93775.481274] hdmitx div40: 0
[93775.502039] hdmitx: system: set mode VIC 16 (cd0,cs0,pm1,vd0,1)
[93775.502056] hdmitx: system: set pll
[93775.502060] hdmitx: system: param->VIC:16
[93775.502065] hdmitx: set clk: VIC = 16  cd = 5  frac_rate = 0
[93775.502075] config HPLL = 3712500
[93775.502094] HPLL: 0xc000029a
[93775.502097] config HPLL done
[93775.503107] set_hpll_od3_clk_div[442] div = 8
[93775.503118] j = 4  vid_clk_div = 1
[93775.503128] hdmitx: set enc for VIC: 16
[93775.503145] hdmitx_set_hw[4999] set VIC = 16
[93775.503388] hdmitx: system: irq 80000001
[93775.519115] Start = 0x10000100   End = 0x100001ff
[93775.519133] [0x10000104]: 0x00000001
[93775.519316] [0x10000180]: 0x000000ff
[93775.519321] [0x10000181]: 0x000000ff
[93775.519325] [0x10000182]: 0x00000003
[93775.519330] [0x10000183]: 0x00000007
[93775.519335] [0x10000184]: 0x0000003f
[93775.519340] [0x10000185]: 0x00000002
[93775.519346] [0x10000187]: 0x000000ff
[93775.519351] [0x10000188]: 0x00000003
[93775.634017] hdmitx: system: PHY Setting Done
[93775.638056] Sink is HDMI device
[93775.638080] hdmitx: system: packet: can't get vendor data
[93775.638090] 1080p60hz 60 1
[93775.638101] 1080p60hz 60 1
[93775.638109] hdmtix: setting audio 1
[93775.638126] hdmitx tx_aud_src = 0
[93775.638173] hdmitx: fs = 2, cd = 5, tmds_clk = 148500
[93775.638182] hdmitx aud_n_para = 6272
[93775.638214] hdmitx set channel status
[93775.638299] hdmitx: audio: Audio Output Channels set to: 2:1
[93775.638336] fb: current vmode=1080p60hz, cmd: 0x10000
[93775.702114] fb: osd[0] enable: 1 (kodi.bin)
[94152.342746] vfm_map_store:rm default
[94152.342781] vfm_map_store:add default decoder ppmgr deinterlace amlvideo amvideo
[94152.343368] codec:vdec_create instance ffffff800474b000, total 1
[94152.344108] codec:Video stbuf alloced at 0000000063b00000, size = 10485760
[94152.344158] codec:vdec_init, dev_name:amvdec_h264, vdec_type=VDEC_TYPE_SINGLE
[94152.344164] codec:vdec_init set vfm decoder ffffff800474b000
[94152.344169] codec:vdec_dev_reg.mem[0x0 -- 0x0]
[94152.344178] codec:vdec base memory alloced [0000000064500000 -- 00000000674fffff]
[94152.345246] codec:H264 sysinfo: 1808x1080 duration=4004, pts_outside=1, 
[94152.345701] codec:vdec_request_irq ffffffc0016d32d0, vh264-irq
[94152.345729] DI: di_receiver_event_fun: vframe provider reg
[94152.348798] audio_dsp: buf=2
[94152.348813] audio_dsp: IEC958_mode_raw=2
[94152.348858] audio_dsp: IEC958_mode_codec= 3, IEC958 type DTS
[94152.348863] audio_dsp: last mode 0,now 3
[94152.355792] set run_early_proc_fun_flag to 1
[94152.355965] codec:vdec_init, vf_provider_name = 
[94152.356703] codec:video first pts = 0
[94152.356715] codec:vdec_request_irq ffffffc0016c4740, parser
[94152.357402] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(0)
[94152.357458] aml_spdif_dai: set normal 512 fs /4 fs
[94152.357467] aml_audio_hw: IEC958 16bit
[94152.357473] hdmitx: audio: aout notify rate 48000
[94152.357477] hdmitx: audio: aout notify size 16
[94152.357481] hdmitx: audio: aout notify sample rate 48000 was 44100
[94152.357486] hdmitx: audio: aout notify format CT_DTS_HD was CT_PCM
[94152.357489] hdmitx: audio: aout notify sample size 1 was 4
[94152.357493] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[94152.357509] hdmtix: setting audio 0
[94152.357520] hdmitx tx_aud_src = 0
[94152.357550] hdmitx: fs = 3, cd = 5, tmds_clk = 148500
[94152.357554] hdmitx aud_n_para = 6144
[94152.357573] hdmitx set channel status
[94152.357632] hdmitx: audio: Audio Output Channels set to: 0:0
[94152.357642] hdmitx: audio: set audio param
[94152.358005] sysfs set hdmi_ch to 0
[94152.358058] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(0)
[94152.358101] aml_spdif_dai: set normal 512 fs /4 fs
[94152.358110] aml_audio_hw: IEC958 16bit
[94152.358140] hdmitx: audio: aout notify rate 48000
[94152.358144] hdmitx: audio: aout notify size 16
[94152.358148] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[94152.358151] hdmitx: audio: no update
[94152.359446] aml_spdif_dai: aiu 958 playback enable
[94152.497898] [tsync_avevent]event:1, param 1
[94152.497917] video pause!
[94152.498744] codec:video_freerun_mode_store(1)
[94152.498976] codec:video first checkin pts = 0
[94152.498994] codec:first check in vpts <0x25:0x0> ok!
[94152.499099] codec:Enter set parameter cmd1.
[94152.499147] codec:vdec1 video changed to 3840 x 2160 60 fps clk->667MHZ
[94152.499158] codec:actual_dpb_size 15 max_dpb_size 3
[94152.499217] codec:v264dec: aspect_ratio not available from source
[94152.499235] codec:video first pts = 1
[94152.546414] pre_de_buf_config: source change: 0x0/0/0/0=>0x9000/1808/1080/0
[94152.546436] DI:7920 disable post.
[94152.590317] codec:video_disable_store(0)
[94152.601732] codec:detect vout mode change!!!!!!!!!!!!
[94152.601764] vpts to scr, apts = 0x0, vpts = 0x0
[94152.601796] codec:[video4osd] first  picture {1808,1080} pts:1,
[94152.618437] codec:VsyncEnableVideoLayer
[94153.042056] aml_spdif_dai: aiu 958 playback disable
[94153.042113] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(0)
[94153.042132] aml_spdif_dai: set normal 512 fs /4 fs
[94153.042144] aml_audio_hw: IEC958 16bit
[94153.042199] hdmitx: audio: aout notify rate 48000
[94153.042205] hdmitx: audio: aout notify size 16
[94153.042209] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[94153.042212] hdmitx: audio: no update
[94153.042882] vout_serve: vmode set to null
[94153.042933] vout_serve: disable HDMI PHY as soon as possible
[94153.042984] fb: current vmode=1080p60hz, cmd: 0x50000
[94153.043015] tv_vout: tv_set_current_vmode[919]fps_target_mode=59
[94153.043021] tv_vout: mode is 59,sync_duration_den=1,sync_duration_num=60
[94153.043032] tv_vout: 3Invalid video output modes.
[94153.043036] tv_vout: new mode =null set ok
[94153.043040] vout_serve: vinfo mode is: null
[94153.043043] vout_serve: new mode null set ok
[94153.043079] hdmitx: edid: not find mapped vic
[94153.043087] hdmitx: video: get current mode: null
[94153.043094] hdmitx: update physcial size: 1650 930
[94153.043100] hdmitx: video: null not valid hdmi mode
[94153.043146] fb: current vmode=null, cmd: 0x10000
[94153.051906] hdmitx: set frac_rate_policy as 1
[94153.051938] vout_serve: vmode set to 1080p24hz
[94153.051961] vout_serve: disable HDMI PHY as soon as possible
[94153.051968] fb: current vmode=null, cmd: 0x50000
[94153.051976] tv_vout: tv_set_current_vmode[919]fps_target_mode=20
[94153.051981] tv_vout: mode is 20,sync_duration_den=125,sync_duration_num=2997
[94153.051992] tv_vout: TV mode 1080p24hz selected.
[94153.051997] 
               vdac_enable: on:0,module_sel:8
[94153.052007] 
               vdac_enable: on:0,module_sel:8
[94153.052016] tv_vout: new mode =1080p24hz set ok
[94153.052020] vout_serve: vinfo mode is: 1080p24hz
[94153.052023] vout_serve: new mode 1080p24hz set ok
[94153.052040] hdmitx: video: get current mode: 1080p24hz
[94153.052044] hdmitx: update rx hdr info 7
[94153.052047] hdmitx: update physcial size: 1650 930
[94153.052089] hdmitx: system: already init VIC = 0  Now VIC = 32
[94153.052094] hdmitx: rx has SCDC present indicator
[94153.054107] hdmirx version is 2.0
[94153.054111] hdmitx div40: 0
[94153.076229] hdmitx: system: set mode VIC 32 (cd0,cs0,pm1,vd0,1)
[94153.076241] hdmitx: system: set pll
[94153.076255] hdmitx: system: param->VIC:32
[94153.076260] hdmitx: set clk: VIC = 32  cd = 5  frac_rate = 1
[94153.076271] config HPLL = 3712500
[94153.076290] HPLL: 0xc000029a
[94153.076293] config HPLL done
[94153.077302] set_hpll_od3_clk_div[442] div = 8
[94153.077310] j = 5  vid_clk_div = 1
[94153.077320] hdmitx: set enc for VIC: 32
[94153.077393] hdmitx_set_hw[4999] set VIC = 32
[94153.077575] hdmitx: system: irq 80000001
[94153.093324] Start = 0x10000100   End = 0x100001ff
[94153.093345] [0x10000104]: 0x00000001
[94153.093524] [0x10000180]: 0x000000ff
[94153.093529] [0x10000181]: 0x000000ff
[94153.093534] [0x10000182]: 0x00000003
[94153.093538] [0x10000183]: 0x00000007
[94153.093543] [0x10000184]: 0x0000003f
[94153.093547] [0x10000185]: 0x00000002
[94153.093553] [0x10000187]: 0x000000ff
[94153.093558] [0x10000188]: 0x00000003
[94153.208232] hdmitx: system: PHY Setting Done
[94153.212256] Sink is HDMI device
[94153.212272] hdmitx: system: packet: can't get vendor data
[94153.212277] 1080p24hz 2997 125
[94153.212282] 1080p24hz 2997 125
[94153.212287] hdmtix: setting audio 1
[94153.212297] hdmitx tx_aud_src = 0
[94153.212322] hdmitx: fs = 3, cd = 5, tmds_clk = 74176
[94153.212327] hdmitx aud_n_para = 11648
[94153.212345] hdmitx set channel status
[94153.212401] hdmitx: audio: Audio Output Channels set to: 0:0
[94153.212460] fb: current vmode=1080p24hz, cmd: 0x10000
[94153.376370] fb: osd[0] enable: 1 (kodi.bin)
[94153.435471] Callback slot table overflowed
[94153.459509] codec:detect vout mode change!!!!!!!!!!!!
[94153.459550] codec:[video4osd] first  picture {1808,1080} pts:2bf2,
[94153.501264] codec:VsyncEnableVideoLayer
[94155.879356] audio_dsp: buf=2
[94155.879369] audio_dsp: IEC958_mode_raw=2
[94155.879405] audio_dsp: IEC958_mode_codec= 3, IEC958 type DTS
[94155.879409] audio_dsp: last mode 2,now 3
[94155.881673] vidioc_qbuf skip: index:740218:740217
[94155.886606] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(0)
[94155.886626] aml_spdif_dai: set normal 512 fs /4 fs
[94155.886632] aml_audio_hw: IEC958 16bit
[94155.886636] hdmitx: audio: aout notify rate 48000
[94155.886641] hdmitx: audio: aout notify size 16
[94155.886644] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[94155.886644] hdmitx: audio: no update
[94155.886863] sysfs set hdmi_ch to 0
[94155.886863] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(0)
[94155.886876] aml_spdif_dai: set normal 512 fs /4 fs
[94155.886881] aml_audio_hw: IEC958 16bit
[94155.886884] hdmitx: audio: aout notify rate 48000
[94155.886885] hdmitx: audio: aout notify size 16
[94155.886888] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[94155.886889] hdmitx: audio: no update
[94155.896493] aml_spdif_dai: aiu 958 playback enable
[94155.920333] codec:[video4osd] first  picture {1808,1080} pts:66a8,
[94155.962104] codec:VsyncEnableVideoLayer
[94156.222202] codec:finished correct frame dur
[94156.222203] codec: new=4005,old_duration=4004,cnt=25
[94175.122353] codec:fix_frame_rate mode play
[94489.836938] codec:DisableVideoLayer()
[94489.861259] DI: di_receiver_event_fun , is_bypass() 1 trick_mode 0 bypass_all 0
[94489.861270] di_receiver_event_fun: vf_notify_receiver unreg
[94489.861283] DI: di_unreg_process unreg start 1.
[94489.861296] codec:DisableVideoLayer()
[94489.861301] codec:disbled keep video before free keep buffer.
[94489.861304] codec:disbled video for next before free keep buffer!
[94489.861308] codec:DisableVideoLayer()
[94489.861314] codec:free_alloced_keep_buffer           (null).          (null).          (null)
[94489.861318] codec:free_alloced_keep_buffer           (null).          (null).          (null)
[94489.861322] [tsync_avevent]event:2, param 0
[94489.861327] codec:video first pts = 0
[94489.861336] DI: di_unreg_process vf unreg cost 0 ms.
[94489.861339] DI: di_unreg_process unreg stop 0.
[94489.872794] codec:vdec1 video changed to 0 x 0 0 fps clk->200MHZ
[94489.873248] codec:video_disable_store(1)
[94489.873260] codec:DisableVideoLayer()
[94489.873266] codec:free_alloced_keep_buffer           (null).          (null).          (null)
[94489.873301] vfm_map_store:rm default
[94489.873327] vfm_map_store:add default  decoder ppmgr deinterlace amlvideo amvideo
[94489.878427] codec:VsyncDisableVideoLayer
[94489.878441] codec:AFBC off now.
[94490.107338] aml_spdif_dai: aiu 958 playback disable
[94490.107410] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=48000, runtime->channels=2, same source mode(0)
[94490.107430] aml_spdif_dai: set normal 512 fs /4 fs
[94490.107438] aml_audio_hw: IEC958 16bit
[94490.107445] hdmitx: audio: aout notify rate 48000
[94490.107448] hdmitx: audio: aout notify size 16
[94490.107453] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[94490.107456] hdmitx: audio: no update
[94490.115572] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=44100, runtime->channels=2, same source mode(1)
[94490.115614] aml_spdif_dai: share the same clock
[94490.115624] aml_audio_hw: IEC958 PCM32
[94490.115630] hdmitx: audio: aout notify rate 44100
[94490.115633] hdmitx: audio: aout notify size 32
[94490.115637] hdmitx: audio: aout notify sample rate 44100 was 48000
[94490.115642] hdmitx: audio: aout notify format CT_PCM was CT_DTS_HD
[94490.115646] hdmitx: audio: aout notify sample size 4 was 1
[94490.115650] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[94490.115665] hdmtix: setting audio 0
[94490.115675] hdmitx tx_aud_src = 0
[94490.115705] hdmitx: fs = 2, cd = 5, tmds_clk = 74176
[94490.115709] hdmitx aud_n_para = 17836
[94490.115731] hdmitx set channel status
[94490.115791] hdmitx: audio: Audio Output Channels set to: 2:1
[94490.115802] hdmitx: audio: set audio param
[94490.115812] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[94490.124410] sysfs set hdmi_ch to 0
[94490.124468] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=44100, runtime->channels=2, same source mode(1)
[94490.124478] aml_spdif_dai: share the same clock
[94490.124497] aml_audio_hw: IEC958 PCM32
[94490.124504] hdmitx: audio: aout notify rate 44100
[94490.124508] hdmitx: audio: aout notify size 32
[94490.124512] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[94490.124516] hdmitx: audio: no update
[94490.124527] aml_snd_m8_card aml_m8_snd.46: i2s/958 same source
[94490.124696] channel count should be 8, we got 2 aborting
6

grab-logs -A completed, but:

Logs available at https://paste.osmc.tv/{"message":"Documentexceedsmaximumlength.
7

Your connection is dropping.
It doesn’t seem to be on the Vero 4K side.

Unfortunately Kodi will freeze sometimes if the remote share becomes inaccessible. However the system will not be unresponsive, and sudo systemctl restart mediacenter will let you restart Kodi. The fact that you can login via SSH shows that the Vero 4K hasn’t actually crashed.

This shouldn’t be happening however. I don’t think you’ve told us how Vero 4K is connected to the network: is it connected via WiFi or Wired?

The log server will only accept 10MB of logs. You could upload these logs to an alternative service; although they shouldn’t be this large unless you have very high uptime.

Sam

8

Hi Sam. Thanks for the diagnosis!
Are you able to see if the connection is dropping from the Vero Side, the server side (or both)?

As of now, both the Vero and the Server are connected through wifi…
The Vero is next to the router, so to make it wired takes just a second, but… unfortunately I don’t have this option for the server. The server is in my detached garage and I don’t have a way to run a cable, so I bought the best wifi extender I could find and that has a wired connection to the server, but the overall connection is wireless.

Are there any buffer settings in Kodi that could mitigate the problem? I’ll try to fix my network issues, but anything helps…

9

Have you tried using Powerline instead of a WiFi extender? You may get better performance that way.

To test the network try using iperf3.

Since the 4K is so close to the router, connect it via a cable to simplify things.

10

Not without detailed logs, no.

Start with the Vero 4K side as it’s the easiest. If you still have problems, then you know where the problem lies.

Unfortunately not – if the connection drops, then buffering won’t remedy that.

11

Unfortunately powerline, even the best, was way worse than the extender.
Iperf3 gives my about 115Mbits/s, that’s why I thought that wifi was good enough.
I’ll connect the ethernet cable to the Vero and see how it goes.
Incidentally I just checked journalctl and dmesg outputs on the server and there was nothing at the time of the crash.

12

Did you tried an extended iperf3 test for 10 or more minutes? Especially with the -i option? That way you can see a drop in the network.

13

What would be a command line to run iperf3 for 10 minutes?

14 
$ iperf3 -c x.x.x.x -i 1 -t 600

Would run connecting to host at ip x.x.x.x for 600 seconds, giving status every second.

15

It doesn’t prove reliability though over such a short test.

Try the Wired approach on the Vero 4K side. If you still have problems, then you know what the issue is.

16

Thanks guys,

iperf3 results:
Vero wifi: 115MBits/s
Vero wired: 95MBits/s
iperf run on my laptop connected to the same ethernet cable used for the previous test: 390MBits/s

So I guess that the wired is slightly slower than wired, but hopefully way more reliable. Also, the bandwidth through the wireless extender seems plenty fast.
I’ll try the Vero wired connection, but I’ll also order a gigabit adapter just in case, to maximize my chances.

17

Those numbers look good. The main thing I was interested in (and why I asked you to do the -i 1 option) was to see if the network is periodically dropping. Did you see any intervals where iperf3 dropped?

18

Definitely less stable when using the -i 1 parameter. What does this parameter do?

19

It gives you status every second. If you don’t get consistent results, it’s because of your network dropping.