Vero 4k crashing intermittently when skipping in video

iamnicolas · 1 June 2021 06:59

Hello, for a while I’ve had a problem on my Vero 4k where when I skip either forward or backwards in a video, OSMC intermittently crashes and the device eventually reboots on its own. I’m able to get back to the same video and watch normally after the reboot. This does not appear to me to be related to a specific file, and seems to me that it happens more often when the device has been on for a while, whereas it seems to be harder to trigger on a fresh reboot. FWIW, I’m running through a Denon AVR-X2300W to an Epson 5050UB. The media is hosted on a NAS and mounted via fstab.

I did not have debug logs enabled when this happened after the device was up for ~7 days, however after enabling debug mode and rebooting, i was able to get a similar crash behavior to happen. In the logs I noticed CAESinkALSA - snd_pcm_writei(-32) Broken pipe - trying to recover.

Debug log link: https://paste.osmc.tv/uxelukigol

Any help or pointers would be appreciated, thanks!

fzinken · 1 June 2021 07:28

Do you see the frowning face? Does just Kodi crash or the whole box reboot?

sam_nazarko · 1 June 2021 09:52

Is this only happening when playing content with a TrueHD track?

Sam

iamnicolas · 2 June 2021 00:15

Thanks for the quick responses! I had to leave for a few days but will respond back when I’m back home and can confirm.

sam_nazarko · 2 June 2021 00:25

You can use https://videosam.pl to drag and drop a file and give us MediaInfo output if not sure.

Sam

iamnicolas · 5 June 2021 03:23

I confirmed this is happening when playing EAC3, so it is not just limited to TrueHD. I checked last and the system is not rebooting, it’s just the frowning face and osmc restarting.

sam_nazarko · 6 June 2021 01:06

Shouldn’t happen with anything over than TrueHD. Can you post some logs to show that?

Sam

iamnicolas · 6 June 2021 19:52

Sure! See new paste @ https://paste.osmc.tv/bumimavule. I downloaded The World in HDR.mkv from https://kodi.wiki/view/Samples#4K_.28UltraHD.29 which is VP9 and Vorbis audio. Similar behavior; I skipped around a bunch to try to re-create the problem and it crashed kodi again.

2021-06-06 11:38:37.058 T:2261655776   DEBUG: Open - av_find_stream_info finished
2021-06-06 11:38:37.058 T:2261655776    INFO: ffmpeg[86CE20E0]: Input #0, matroska,webm, from '/mnt/video/movies/hd/!test/The World in HDR.mkv':
2021-06-06 11:38:37.059 T:2261655776    INFO: ffmpeg[86CE20E0]:   Metadata:
2021-06-06 11:38:37.059 T:2261655776    INFO: ffmpeg[86CE20E0]:     encoder         : libebml v1.3.4 + libmatroska v1.4.5
2021-06-06 11:38:37.059 T:2261655776    INFO: ffmpeg[86CE20E0]:     creation_time   : 2016-11-08T02:38:04.000000Z
2021-06-06 11:38:37.059 T:2261655776    INFO: ffmpeg[86CE20E0]:   Duration: 00:02:34.57, start: 0.000000, bitrate: 18316 kb/s
2021-06-06 11:38:37.059 T:2261655776    INFO: ffmpeg[86CE20E0]:     Stream #0:0(eng): Video: vp9 (Profile 2), yuv420p10le(tv, bt2020nc/bt2020/smpte2084), 3840x2160, SAR 1:1 DAR 16:9, 59.94 fps, 59.94 tbr, 1k tbn, 1k tbc (default)
2021-06-06 11:38:37.059 T:2261655776    INFO: ffmpeg[86CE20E0]:     Metadata:
2021-06-06 11:38:37.059 T:2261655776    INFO: ffmpeg[86CE20E0]:       BPS             : 18203235
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       BPS-eng         : 18203235
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       DURATION        : 00:02:34.555000000
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       DURATION-eng    : 00:02:34.555000000
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       NUMBER_OF_FRAMES: 9264
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       NUMBER_OF_FRAMES-eng: 9264
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       NUMBER_OF_BYTES : 351675124
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       NUMBER_OF_BYTES-eng: 351675124
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_WRITING_APP: mkvmerge v9.5.0 ('Quiet Fire') 64bit
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_WRITING_APP-eng: mkvmerge v9.5.0 ('Quiet Fire') 64bit
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_WRITING_DATE_UTC: 2016-11-08 02:38:04
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_WRITING_DATE_UTC-eng: 2016-11-08 02:38:04
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_TAGS: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_TAGS-eng: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:     Side data:
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       Mastering Display Metadata, has_primaries:1 has_luminance:1 r(0.6800,0.3200) g(0.2649,0.6900) b(0.1500 0.0600) wp(0.3127, 0.3127) min_luminance=0.001000, max_luminance=1000.000000
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:     Stream #0:1(eng): Audio: vorbis, 44100 Hz, stereo, fltp (default)
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:     Metadata:
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       BPS             : 109558
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       BPS-eng         : 109558
2021-06-06 11:38:37.060 T:2261655776    INFO: ffmpeg[86CE20E0]:       DURATION        : 00:02:34.569000000
2021-06-06 11:38:37.061 T:2261655776    INFO: ffmpeg[86CE20E0]:       DURATION-eng    : 00:02:34.569000000
2021-06-06 11:38:37.061 T:2261655776    INFO: ffmpeg[86CE20E0]:       NUMBER_OF_FRAMES: 7450
2021-06-06 11:38:37.061 T:2261655776    INFO: ffmpeg[86CE20E0]:       NUMBER_OF_FRAMES-eng: 7450
2021-06-06 11:38:37.061 T:2261655776    INFO: ffmpeg[86CE20E0]:       NUMBER_OF_BYTES : 2116797
2021-06-06 11:38:37.061 T:2261655776    INFO: ffmpeg[86CE20E0]:       NUMBER_OF_BYTES-eng: 2116797
2021-06-06 11:38:37.061 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_WRITING_APP: mkvmerge v9.5.0 ('Quiet Fire') 64bit
2021-06-06 11:38:37.061 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_WRITING_APP-eng: mkvmerge v9.5.0 ('Quiet Fire') 64bit
2021-06-06 11:38:37.061 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_WRITING_DATE_UTC: 2016-11-08 02:38:04
2021-06-06 11:38:37.061 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_WRITING_DATE_UTC-eng: 2016-11-08 02:38:04
2021-06-06 11:38:37.061 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_TAGS: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES
2021-06-06 11:38:37.061 T:2261655776    INFO: ffmpeg[86CE20E0]:       _STATISTICS_TAGS-eng: BPS DURATION NUMBER_OF_FRAMES NUMBER_OF_BYTES

After skipping around a bunch while the video was playing, similar errors show up in the log and it crashes:

2021-06-06 11:40:10.234 T:2261655776   DEBUG: SeekTime - seek ended up on time 5.071
2021-06-06 11:40:10.234 T:2261655776   DEBUG: CVideoPlayer::FlushBuffers - flushing buffers
2021-06-06 11:40:10.237 T:2211299552   DEBUG: CAMLCodec::Reset
2021-06-06 11:40:10.277 T:2253263072   DEBUG: CDVDAudio::Flush - flush audio stream
2021-06-06 11:40:10.277 T:2253263072   DEBUG: CDVDAudio::Pause - pausing audio stream
2021-06-06 11:40:10.296 T:2211299552   DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_SYNCHRONIZE
2021-06-06 11:40:10.297 T:2261655776   DEBUG: CVideoPlayer - CDVDMsg::GENERAL_SYNCHRONIZE
2021-06-06 11:40:10.298 T:2253263072   DEBUG: CVideoPlayerAudio - CDVDMsg::GENERAL_SYNCHRONIZE
2021-06-06 11:40:10.300 T:4068057104   DEBUG: ------ Window Init (DialogSeekBar.xml) ------
2021-06-06 11:40:10.313 T:4068057104   DEBUG: ------ Window Init (Custom_1109_TopBarOverlay.xml) ------
2021-06-06 11:40:10.314 T:2286870752   DEBUG: ffmpeg[884EE0E0]: [swscaler] No accelerated colorspace conversion found from yuv420p to bgra.
2021-06-06 11:40:10.319 T:3813621984   DEBUG: Skin Helper Widgets --> Kodi_Monitor: sender xbmc - method: Player.OnSeek  - data: {"item":{"id":961,"type":"movie"},"player":{"playerid":1,"seekoffset":{"hours":0,"milliseconds":-457,"minutes":0,"seconds":-15},"speed":1,"time":{"hours":0,"milliseconds":526,"minutes":0,"seconds":5}}}
2021-06-06 11:40:10.372 T:3847192800   DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Player.OnSeek  - data: {"item":{"id":961,"type":"movie"},"player":{"playerid":1,"seekoffset":{"hours":0,"milliseconds":-457,"minutes":0,"seconds":-15},"speed":1,"time":{"hours":0,"milliseconds":526,"minutes":0,"seconds":5}}}
2021-06-06 11:40:10.427 T:2211299552    INFO: CVideoPlayerVideo - Stillframe left, switching to normal playback
2021-06-06 11:40:10.431 T:2211299552   DEBUG:  frame_number : 2, mag : 3; index_sz : 8
2021-06-06 11:40:10.446 T:2261655776   DEBUG: Previous line repeats 1 times.
2021-06-06 11:40:10.446 T:2261655776   DEBUG: CVideoPlayer::HandleMessages - player started 1
2021-06-06 11:40:10.447 T:2324435168   DEBUG: OnAVChange: CApplication::OnAVChange
2021-06-06 11:40:10.453 T:2211299552   DEBUG:  frame_number : 2, mag : 3; index_sz : 8
2021-06-06 11:40:10.473 T:3847192800   DEBUG: Skin Helper Service --> Kodi_Monitor: sender xbmc - method: Player.OnAVChange  - data: {"item":{"id":961,"type":"movie"},"player":{"playerid":1,"speed":1}}
2021-06-06 11:40:10.519 T:3813621984   DEBUG: Skin Helper Widgets --> Kodi_Monitor: sender xbmc - method: Player.OnAVChange  - data: {"item":{"id":961,"type":"movie"},"player":{"playerid":1,"speed":1}}
2021-06-06 11:40:10.662 T:2261655776   DEBUG: CVideoPlayer::HandleMessages - player started 2
2021-06-06 11:40:10.662 T:2261655776   DEBUG: VideoPlayer::Sync - Audio - pts: 5377000.000000, cache: 430553.406966, totalcache: 785759.627819
2021-06-06 11:40:10.662 T:2261655776   DEBUG: VideoPlayer::Sync - Video - pts: 5071000.000000, cache: 50000.000000, totalcache: 100000.000000
2021-06-06 11:40:10.663 T:2261655776   DEBUG: CDVDClock::SetSpeedAdjust - adjusted:0.000000
2021-06-06 11:40:10.663 T:2253263072   DEBUG: CVideoPlayerAudio - CDVDMsg::GENERAL_RESYNC(4946446.593034), level: 6, cache: 443906.199383
2021-06-06 11:40:10.663 T:2211299552   DEBUG: CVideoPlayerVideo - CDVDMsg::GENERAL_RESYNC(4946446.593034)
2021-06-06 11:40:10.663 T:2253263072   DEBUG: CDVDAudio::Resume - resume audio stream
2021-06-06 11:40:10.665 T:2211299552   DEBUG: CAMLCodec::SetSpeed, speed(1000)
2021-06-06 11:40:10.667 T:4026527968   DEBUG: ActiveAE - start sync of audio stream
2021-06-06 11:40:10.668 T:2211299552   DEBUG:  frame_number : 2, mag : 3; index_sz : 8
2021-06-06 11:40:10.788 T:4026527968   DEBUG: Previous line repeats 3 times.
2021-06-06 11:40:10.788 T:4026527968   DEBUG: ActiveAE::SyncStream - average error of -0.750137, start adjusting
2021-06-06 11:40:10.788 T:4026527968   DEBUG: ActiveAE::SyncStream - average error -0.001837 below threshold of 30.000000
2021-06-06 11:40:10.824 T:2211299552   DEBUG:  frame_number : 2, mag : 3; index_sz : 8
2021-06-06 11:40:11.813 T:2253263072   DEBUG: Previous line repeats 14 times.
2021-06-06 11:40:11.813 T:2253263072   DEBUG: CDVDClock::ErrorAdjust - CVideoPlayerAudio::OutputPacket - error:-29794.715460, adjusted:-16683.333333
2021-06-06 11:40:11.820 T:2211299552   DEBUG:  frame_number : 2, mag : 3; index_sz : 8
2021-06-06 11:40:12.726 T:2211299552   DEBUG: Previous line repeats 9 times.
2021-06-06 11:40:12.726 T:2211299552   DEBUG: CPtsTracker: detected pattern of length 1: 16683.33, frameduration: 16683.333333
2021-06-06 11:40:12.806 T:2211299552   DEBUG:  frame_number : 2, mag : 3; index_sz : 8
2021-06-06 11:40:12.949 T:4068057104   DEBUG: Previous line repeats 1 times.
2021-06-06 11:40:12.949 T:4068057104   DEBUG: ------ Window Deinit (DialogSeekBar.xml) ------
2021-06-06 11:40:12.962 T:4068057104   DEBUG: ------ Window Deinit (Custom_1109_TopBarOverlay.xml) ------
2021-06-06 11:40:13.022 T:2211299552   DEBUG:  frame_number : 2, mag : 3; index_sz : 8
2021-06-06 11:40:14.704 T:2211299552   DEBUG: Previous line repeats 14 times.
2021-06-06 11:40:14.704 T:2211299552   DEBUG:  frame_number : 2, mag : 2; index_sz : 6
2021-06-06 11:40:14.797 T:2211299552   DEBUG:  frame_number : 2, mag : 3; index_sz : 8
2021-06-06 11:40:22.199 T:2211299552   DEBUG: Previous line repeats 71 times.
2021-06-06 11:40:22.208 T:2211299552   DEBUG:  frame_number : 2, mag : 2; index_sz : 6
2021-06-06 11:40:22.294 T:2211299552   DEBUG:  frame_number : 2, mag : 3; index_sz : 8
2021-06-06 11:40:28.432 T:2253263072   DEBUG: Previous line repeats 7 times.
2021-06-06 11:40:28.632 T:2253263072   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2021-06-06 11:40:28.632 T:4016042208   ERROR: CAESinkALSA - snd_pcm_writei(-32) Broken pipe - trying to recover
2021-06-06 11:40:28.899 T:2211299552   DEBUG:  frame_number : 2, mag : 3; index_sz : 8
2021-06-06 11:40:30.566 T:4026527968 WARNING: ActiveAE - large audio sync error: -4201.668118
2021-06-06 11:40:30.825 T:4026527968   DEBUG: ActiveAE::SyncStream - average error -436.341836 above threshold of 100.000000
2021-06-06 11:40:30.915 T:2253263072   ERROR: CDVDAudio::AddPacketsRenderer - timeout adding data to renderer
2021-06-06 11:40:31.043 T:2253263072   DEBUG: CDVDClock::ErrorAdjust - CVideoPlayerAudio::OutputPacket - error:-56623.078409, adjusted:-16683.333333
2021-06-06 11:40:31.044 T:4026527968   DEBUG: ActiveAE::SyncStream - average error -18.382652 below threshold of 30.000000
2021-06-06 11:40:31.044 T:4026527968 WARNING: ActiveAE - large audio sync error: -4356.895784
2021-06-06 11:40:31.490 T:4016042208   ERROR: CAESinkALSA - snd_pcm_writei(-32) Broken pipe - trying to recover
2021-06-06 11:40:31.514 T:4026527968 WARNING: ActiveAE - large audio sync error: -4823.378697
2021-06-06 11:40:31.514 T:4026527968 WARNING: ActiveAE - large audio sync error: -4823.819273
2021-06-06 11:40:31.515 T:4026527968 WARNING: ActiveAE - large audio sync error: -4824.257849
2021-06-06 11:40:32.109 T:4016042208   ERROR: CAESinkALSA - snd_pcm_writei(-32) Broken pipe - trying to recover

---------------------- Kodi Old Log END --------------- 2qaAc90c

sam_nazarko · 7 June 2021 13:11

Can you try playing this file from local storage?

iamnicolas · 7 June 2021 18:27

Tried from local sd card storage just now; unable to reproduce.

sam_nazarko · 7 June 2021 20:20

Okay, can you tell us more about the device you are streaming from?

iamnicolas · 8 June 2021 01:15

It’s a Synology DS418 (link).

Not sure how relevant it is, but here’s some iperf data from the Vero 4k to the NAS:

osmc@mediakodi:~$ iperf3 -R -c 192.168.86.236
Connecting to host 192.168.86.236, port 5201
Reverse mode, remote host 192.168.86.236 is sending
[  5] local 192.168.86.39 port 51938 connected to 192.168.86.236 port 5201
[ ID] Interval           Transfer     Bitrate
[  5]   0.00-1.00   sec  11.2 MBytes  93.7 Mbits/sec
[  5]   1.00-2.00   sec  11.1 MBytes  93.4 Mbits/sec
[  5]   2.00-3.00   sec  11.1 MBytes  93.2 Mbits/sec
[  5]   3.00-4.00   sec  11.2 MBytes  93.5 Mbits/sec
[  5]   4.00-5.00   sec  11.1 MBytes  93.3 Mbits/sec
[  5]   5.00-6.00   sec  11.2 MBytes  93.6 Mbits/sec
[  5]   6.00-7.00   sec  11.1 MBytes  93.2 Mbits/sec
[  5]   7.00-8.00   sec  11.1 MBytes  93.5 Mbits/sec
[  5]   8.00-9.00   sec  11.1 MBytes  93.3 Mbits/sec
[  5]   9.00-10.00  sec  11.2 MBytes  93.6 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bitrate         Retr
[  5]   0.00-10.01  sec   112 MBytes  94.0 Mbits/sec    0             sender
[  5]   0.00-10.00  sec   111 MBytes  93.4 Mbits/sec                  receiver

iperf Done.
osmc@mediakodi:~$ iperf3 -c 192.168.86.236
Connecting to host 192.168.86.236, port 5201
[  5] local 192.168.86.39 port 51940 connected to 192.168.86.236 port 5201
[ ID] Interval           Transfer     Bitrate         Retr  Cwnd
[  5]   0.00-1.00   sec  12.3 MBytes   103 Mbits/sec    0    274 KBytes
[  5]   1.00-2.00   sec  11.7 MBytes  98.1 Mbits/sec    0    409 KBytes
[  5]   2.00-3.00   sec  12.3 MBytes   104 Mbits/sec    0    513 KBytes
[  5]   3.00-4.00   sec  10.8 MBytes  90.9 Mbits/sec    0    609 KBytes
[  5]   4.00-5.00   sec  12.2 MBytes   102 Mbits/sec    0    628 KBytes
[  5]   5.00-6.00   sec  11.2 MBytes  94.2 Mbits/sec    0    670 KBytes
[  5]   6.00-7.00   sec  11.2 MBytes  94.4 Mbits/sec    0    707 KBytes
[  5]   7.00-8.00   sec  11.2 MBytes  94.4 Mbits/sec    0    764 KBytes
[  5]   8.00-9.00   sec  10.0 MBytes  83.9 Mbits/sec    0    778 KBytes
[  5]   9.00-10.00  sec  11.2 MBytes  94.4 Mbits/sec    0    826 KBytes
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bitrate         Retr
[  5]   0.00-10.00  sec   114 MBytes  95.9 Mbits/sec    0             sender
[  5]   0.00-10.06  sec   112 MBytes  93.6 Mbits/sec                  receiver

iperf Done.

iamnicolas · 10 June 2021 00:26

Had this happen again so i went ahead and enabled component logging for the audio and video related components and triggered this again. Also captured the sudo dmesg output. Looks like there was an OOM issue?

Latest logs including the audio/video components (i had to extract just the last couple minutes because the log file was too large to upload apparently): https://paste.osmc.tv/urumowihuz

relevant dmesg info:

[Wed Jun  9 16:57:02 2021] pre_de_buf_config: source change: 0x0/0/0/0=>0x501000/3840/2160/0
[Wed Jun  9 16:57:02 2021] DI:7920 disable post.
[Wed Jun  9 16:57:07 2021] aml_snd_m8_card aml_m8_snd.46: I2S playback disable
[Wed Jun  9 16:57:07 2021] aml_snd_m8_card aml_m8_snd.46: IEC958 playback disable
[Wed Jun  9 16:57:09 2021] i2s/958 same source - init spdif
[Wed Jun  9 16:57:09 2021] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=44100, runtime->channels=2, same source mode(1), stream format=1
[Wed Jun  9 16:57:09 2021] aml_spdif_dai: set divider = 2 for i2s shared clock
[Wed Jun  9 16:57:09 2021] aml_audio_hw: IEC958 PCM32
[Wed Jun  9 16:57:09 2021] hdmitx: audio: aout notify rate 44100
[Wed Jun  9 16:57:09 2021] hdmitx: audio: aout notify size 32
[Wed Jun  9 16:57:09 2021] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[Wed Jun  9 16:57:09 2021] hdmitx: audio: no update
[Wed Jun  9 16:57:10 2021] aml_snd_m8_card aml_m8_snd.46: I2S playback enable
[Wed Jun  9 16:57:10 2021] aml_snd_m8_card aml_m8_snd.46: IEC958 playback enable
[Wed Jun  9 16:57:10 2021] aml_snd_m8_card aml_m8_snd.46: I2S playback disable
[Wed Jun  9 16:57:10 2021] aml_snd_m8_card aml_m8_snd.46: IEC958 playback disable
[Wed Jun  9 16:57:10 2021] i2s/958 same source - init spdif
[Wed Jun  9 16:57:10 2021] aml_spdif_dai: aml_hw_iec958_init,runtime->rate=44100, runtime->channels=2, same source mode(1), stream format=1
[Wed Jun  9 16:57:10 2021] aml_spdif_dai: set divider = 2 for i2s shared clock
[Wed Jun  9 16:57:10 2021] aml_audio_hw: IEC958 PCM32
[Wed Jun  9 16:57:10 2021] hdmitx: audio: aout notify rate 44100
[Wed Jun  9 16:57:10 2021] hdmitx: audio: aout notify size 32
[Wed Jun  9 16:57:10 2021] hdmitx: audio: hdmi_ch: 0 speaker_layout: 0
[Wed Jun  9 16:57:10 2021] hdmitx: audio: no update
[Wed Jun  9 16:57:10 2021] aml_snd_m8_card aml_m8_snd.46: I2S playback enable
[Wed Jun  9 16:57:10 2021] aml_snd_m8_card aml_m8_snd.46: IEC958 playback enable
[Wed Jun  9 16:57:12 2021] FileCache invoked oom-killer: gfp_mask=0x200da, order=0, oom_score_adj=0
[Wed Jun  9 16:57:12 2021] FileCache cpuset=/ mems_allowed=0
[Wed Jun  9 16:57:12 2021] CPU: 1 PID: 2719 Comm: FileCache Tainted: G           O 3.14.29-160-osmc #1
[Wed Jun  9 16:57:12 2021] Call trace:
[Wed Jun  9 16:57:12 2021] [<ffffffc001087718>] dump_backtrace+0x0/0x130
[Wed Jun  9 16:57:12 2021] [<ffffffc001087868>] show_stack+0x20/0x30
[Wed Jun  9 16:57:12 2021] [<ffffffc0018a1684>] dump_stack+0x78/0x94
[Wed Jun  9 16:57:12 2021] [<ffffffc001144ae4>] dump_header.isra.5+0x84/0x1c8
[Wed Jun  9 16:57:12 2021] [<ffffffc0011452c8>] oom_kill_process+0x390/0x428
[Wed Jun  9 16:57:12 2021] [<ffffffc001145850>] out_of_memory+0x2f0/0x340
[Wed Jun  9 16:57:12 2021] [<ffffffc00114b8e0>] __alloc_pages_nodemask+0xa58/0xa70
[Wed Jun  9 16:57:12 2021] [<ffffffc00116fb9c>] handle_mm_fault+0x784/0xc48
[Wed Jun  9 16:57:12 2021] [<ffffffc00108fa28>] do_page_fault+0xd8/0x290
[Wed Jun  9 16:57:12 2021] [<ffffffc00108123c>] do_mem_abort+0x4c/0xa8
[Wed Jun  9 16:57:12 2021] Exception stack(0xffffffc05e807e30 to 0xffffffc05e807f50)
[Wed Jun  9 16:57:12 2021] 7e20:                                     00000000 00000000 00000000 00000000
[Wed Jun  9 16:57:12 2021] 7e40: ffffffff ffffffff f603ff38 00000000 5e807e90 ffffffc0 0119fbec ffffffc0
[Wed Jun  9 16:57:12 2021] 7e60: 5d25ca03 ffffffc0 5d25ca00 ffffffc0 5e807e90 ffffffc0 0119fc2c ffffffc0
[Wed Jun  9 16:57:12 2021] 7e80: 5d25ca03 ffffffc0 00000011 00000000 5e807eb0 ffffffc0 010873b4 ffffffc0
[Wed Jun  9 16:57:12 2021] 7ea0: 00400008 00000000 5e807ed0 ffffffc0 00000000 00000000 010842d4 ffffffc0
[Wed Jun  9 16:57:12 2021] 7ec0: 00000000 00000000 00000000 00000000 7695b4c8 00000000 cdacad08 00000000
[Wed Jun  9 16:57:12 2021] 7ee0: 00020000 00000000 00000000 00000000 00020000 00000000 c3035128 00000000
[Wed Jun  9 16:57:12 2021] 7f00: 00000000 00000000 c30351e4 00000000 0001c280 00000000 00020000 00000000
[Wed Jun  9 16:57:12 2021] 7f20: cdac7228 00000000 c1c87890 00000000 7695ef88 00000000 8cafe6f4 00000000
[Wed Jun  9 16:57:12 2021] 7f40: aba9b85b 00000000 00000000 00000000
[Wed Jun  9 16:57:12 2021] Mem-Info:
[Wed Jun  9 16:57:12 2021] Normal per-cpu:
[Wed Jun  9 16:57:12 2021] CPU    0: hi:  186, btch:  31 usd:   0
[Wed Jun  9 16:57:12 2021] CPU    1: hi:  186, btch:  31 usd:   0
[Wed Jun  9 16:57:12 2021] CPU    2: hi:  186, btch:  31 usd:   0
[Wed Jun  9 16:57:12 2021] CPU    3: hi:  186, btch:  31 usd:   0
[Wed Jun  9 16:57:12 2021] active_anon:350251 inactive_anon:4128 isolated_anon:0
                            active_file:831 inactive_file:1728 isolated_file:96
                            unevictable:0 dirty:0 writeback:0 unstable:0
                            free:8178 slab_reclaimable:2791 slab_unreclaimable:4139
                            mapped:3648 shmem:4227 pagetables:1221 bounce:0 used_cma:43641
                            cma:0 anon_cma:17541 file_cma:245 isolate_cma:0
                            isolate:0
                            unmovable:5957 reclaimable:1889 movable:419 reserve:0
[Wed Jun  9 16:57:12 2021] Normal free:32712kB min:32768kB low:40960kB high:49152kB active_anon:1401004kB inactive_anon:16512kB active_file:3324kB inactive_file:6912kB unevictable:0kB isolated(anon):0kB isolated(file):256kB present:1978368kB managed:1764120kB mlocked:0kB dirty:0kB writeback:0kB mapped:14592kB shmem:16908kB slab_reclaimable:11164kB slab_unreclaimable:16556kB kernel_stack:3504kB pagetables:4884kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:16375 all_unreclaimable? yes
[Wed Jun  9 16:57:12 2021] lowmem_reserve[]: 0 0
[Wed Jun  9 16:57:12 2021] Normal: 657*4kB (UEM) 634*8kB (UEM) 403*16kB (UEM) 201*32kB (UEM) 71*64kB (UEM) 36*128kB (UEM) 13*256kB (UE) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 33060kB
[Wed Jun  9 16:57:12 2021] 6882 total pagecache pages
[Wed Jun  9 16:57:12 2021] 0 pages in swap cache
[Wed Jun  9 16:57:12 2021] Swap cache stats: add 0, delete 0, find 0/0
[Wed Jun  9 16:57:12 2021] Free swap  = 0kB
[Wed Jun  9 16:57:12 2021] Total swap = 0kB
[Wed Jun  9 16:57:12 2021] 494592 pages RAM
[Wed Jun  9 16:57:12 2021] 0 pages HighMem/MovableOnly
[Wed Jun  9 16:57:12 2021] 53562 pages reserved
[Wed Jun  9 16:57:12 2021] [ pid ]   uid  tgid total_vm      rss nr_ptes swapents oom_score_adj name
[Wed Jun  9 16:57:12 2021] [  181]     0   181     8816     3094      41        0             0 systemd-journal
[Wed Jun  9 16:57:12 2021] [  213]   104   213     1343       81       6        0             0 rpcbind
[Wed Jun  9 16:57:12 2021] [  224]     0   224     3991      209       8        0         -1000 systemd-udevd
[Wed Jun  9 16:57:12 2021] [  241]     0   241     2735      171       9        0             0 systemd-logind
[Wed Jun  9 16:57:12 2021] [  243]   108   243     1281      113       5        0             0 avahi-daemon
[Wed Jun  9 16:57:12 2021] [  244]   106   244     1448      165       6        0          -900 dbus-daemon
[Wed Jun  9 16:57:12 2021] [  250]     0   250     2182      106       8        0             0 wpa_supplicant
[Wed Jun  9 16:57:12 2021] [  251]     0   251      460       37       5        0             0 eventlircd
[Wed Jun  9 16:57:12 2021] [  266]   108   266     1248       69       5        0             0 avahi-daemon
[Wed Jun  9 16:57:12 2021] [  335]     0   335     2711      155       9        0             0 connmand
[Wed Jun  9 16:57:12 2021] [  342]     0   342     1006       58       6        0             0 lircd
[Wed Jun  9 16:57:12 2021] [  442]     0   442     1006       61       6        0             0 lircd
[Wed Jun  9 16:57:12 2021] [  496]  1000   496     2046      135       7        0             0 udisks-glue
[Wed Jun  9 16:57:12 2021] [  498]     0   498     6964      197      12        0             0 udisks-daemon
[Wed Jun  9 16:57:12 2021] [  499]     0   499     2151       93       8        0             0 udisks-daemon
[Wed Jun  9 16:57:12 2021] [  502]     0   502     9103      193      14        0             0 polkitd
[Wed Jun  9 16:57:12 2021] [  630]     0   630     2265      146       8        0         -1000 sshd
[Wed Jun  9 16:57:12 2021] [  752]     0   752      373       20       4        0             0 hciattach
[Wed Jun  9 16:57:12 2021] [  755]     0   755     1379       64       7        0             0 bluetoothd
[Wed Jun  9 16:57:12 2021] [  796]     0   796     6264      354      15        0             0 nmbd
[Wed Jun  9 16:57:12 2021] [  797]     0   797     1154       63       7        0             0 mediacenter
[Wed Jun  9 16:57:12 2021] [  816]     0   816      905       30       5        0             0 agetty
[Wed Jun  9 16:57:12 2021] [  859]     0   859     9689      492      22        0             0 smbd
[Wed Jun  9 16:57:12 2021] [  925]     0   925     1693       88       7        0             0 sudo
[Wed Jun  9 16:57:12 2021] [  934]  1000   934   582326   345966     887        0             0 kodi.bin
[Wed Jun  9 16:57:12 2021] [  936]     0   936     9124      469      21        0             0 smbd-notifyd
[Wed Jun  9 16:57:12 2021] [  937]     0   937     9125      469      21        0             0 cleanupd
[Wed Jun  9 16:57:12 2021] [ 1047]   105  1047     1838      118       7        0             0 ntpd
[Wed Jun  9 16:57:12 2021] [ 1053]     0  1053     2602      194      10        0             0 sshd
[Wed Jun  9 16:57:12 2021] [ 1093]  1000  1093     2989      232       9        0             0 systemd
[Wed Jun  9 16:57:12 2021] [ 1098]  1000  1098     3540      399      10        0             0 (sd-pam)
[Wed Jun  9 16:57:12 2021] [ 1114]  1000  1114     2645      271      10        0             0 sshd
[Wed Jun  9 16:57:12 2021] [ 1119]  1000  1119      749      127       5        0             0 bash
[Wed Jun  9 16:57:12 2021] Out of memory: Kill process 934 (kodi.bin) score 786 or sacrifice child
[Wed Jun  9 16:57:12 2021] Killed process 934 (kodi.bin) total-vm:2329304kB, anon-rss:1381708kB, file-rss:2156kB
[Wed Jun  9 16:57:12 2021] aml_snd_m8_card aml_m8_snd.46: I2S playback disable
[Wed Jun  9 16:57:12 2021] aml_snd_m8_card aml_m8_snd.46: IEC958 playback disable
[Wed Jun  9 16:57:13 2021] DI: di_receiver_event_fun , is_bypass() 1 trick_mode 0 bypass_all 0
[Wed Jun  9 16:57:13 2021] di_receiver_event_fun: vf_notify_receiver unreg
[Wed Jun  9 16:57:13 2021] DI: di_unreg_process unreg start 1.

fzinken · 10 June 2021 01:02

Might not be related but it looks like that you configured kernel mounts in fstab it seems still that there are some direct NFS access entries (maybe because of your central Database. May want to check if you need to use pathsubstituion or clean up the database.

2021-06-09 17:03:47.709 T:2644685024   DEBUG: NFS: Refreshing context for 192.168.86.236/volume1/music, old: 381882, new: 381900
2021-06-09 17:03:47.709 T:2644685024   DEBUG: NFS: Using cached context.