Kodi Community Forum

Full Version: SMB Files need to be started 2 or 3 times
You're currently viewing a stripped down version of our content. View the full version with proper formatting.
I'm having an odd problem where files on my network shares wont play the first time I click them. Sometimes it takes 2, other times 3 or 4 clicks before they start.

This seems to be happening only when I play them from my movie library, not if I navigate to the share using the Files menu.

I am using KODI 16 Beta 4 on 2 different Android Boxes and 1 PC running Ubuntu. I have MariaDB running the shared database on the Ubuntu PC.

My files are on 2 different NAS (one custom build Ubuntu server and the other a Buffalo Link Station) and the same thing happens on all the players (both Android ones and Linux) with files from both NASs.

The log shows the same in every case:

Code:
11:36:24 T:140540175100032   DEBUG: ProcessMouse: trying mouse action leftclick
11:36:24 T:140540175100032   DEBUG: CAnnouncementManager - Announcement: OnClear from xbmc
11:36:24 T:140540175100032   DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnClear
11:36:24 T:140540175100032   DEBUG: Loading settings for smb://CASTLE/Movies/We Are Your Friends.mkv
11:36:24 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers(smb://CASTLE/Movies/We Are Your Friends.mkv)
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: system rules
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: mms/udp
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtmp
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtsp
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: streams
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvd
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvdimage
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: nsv
11:36:24 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: radio
11:36:24 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: matched 0 rules with players
11:36:24 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (1)
11:36:24 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
11:36:24 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
11:36:24 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: adding player: DVDPlayer (1)
11:36:24 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: added 1 players
11:36:24 T:140540175100032   DEBUG: Radio UECP (RDS) Processor - new CDVDRadioRDSData
11:36:24 T:140540175100032  NOTICE: DVDPlayer: Opening: smb://CASTLE/Movies/We Are Your Friends.mkv
11:36:24 T:140540175100032 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
11:36:24 T:140540175100032   DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
11:36:24 T:140540175100032   DEBUG: LinuxRendererGL: Cleaning up GL resources
11:36:24 T:140540175100032   DEBUG: CLinuxRendererGL::PreInit - precision of luminance 16 is 16
11:36:24 T:140539693541120   DEBUG: Thread DVDPlayer start, auto delete: false
11:36:24 T:140539693541120  NOTICE: Creating InputStream
11:36:24 T:140540175100032   DEBUG: ------ Window Init (DialogBusy.xml) ------
11:36:24 T:140540175100032   DEBUG: ------ Window Init (Pointer.xml) ------
11:36:30 T:140539693541120   DEBUG: CSMBFile::Open - opened smb://CASTLE/Movies/We Are Your Friends.mkv, fd=-1
11:36:30 T:140539693541120    INFO: SMBFile->Open: Unable to open file : 'smb://USERNAME:[email protected]/Movies/We%20Are%20Your%20Friends%20.mkv'
                                            unix_err:'d' error : 'Permission denied'
11:36:30 T:140539693541120   ERROR: CDVDPlayer::OpenInputStream - error opening [smb://CASTLE/Movies/We Are Your Friends.mkv]
11:36:30 T:140539693541120  NOTICE: CDVDPlayer::OnExit()
11:36:30 T:140539693541120   DEBUG: OnPlayBackStopped: play state was 1, starting 1
11:36:30 T:140539693541120   DEBUG: Thread DVDPlayer 140539693541120 terminating
11:36:30 T:140540175100032   DEBUG: OnPlayBackStopped: play state was 3, starting 0
11:36:30 T:140540175100032   DEBUG: CAnnouncementManager - Announcement: OnStop from xbmc
11:36:30 T:140540175100032   DEBUG: GOT ANNOUNCEMENT, type: 1, from xbmc, message OnStop
11:36:30 T:140540175100032   ERROR: PlayMedia could not play media: smb://CASTLE/Movies/We Are Your Friends.mkv
11:36:30 T:140540175100032  NOTICE: CDVDPlayer::CloseFile()
11:36:30 T:140540175100032  NOTICE: DVDPlayer: waiting for threads to exit
11:36:30 T:140540175100032  NOTICE: DVDPlayer: finished waiting
11:36:30 T:140540175100032   DEBUG: LinuxRendererGL: Cleaning up GL resources
11:36:30 T:140540175100032  NOTICE: CDVDPlayer::CloseFile()
11:36:30 T:140540175100032  NOTICE: DVDPlayer: waiting for threads to exit
11:36:30 T:140540175100032  NOTICE: DVDPlayer: finished waiting
11:36:30 T:140540175100032   DEBUG: LinuxRendererGL: Cleaning up GL resources
11:36:30 T:140540175100032   DEBUG: Radio UECP (RDS) Processor - delete ~CDVDRadioRDSData
11:36:30 T:140540175100032   DEBUG: ------ Window Deinit (DialogBusy.xml) ------
11:36:30 T:140539693541120   DEBUG: Thread JobWorker start, auto delete: true
11:36:30 T:140539693541120   DEBUG: DoWork - Saving file state for video item smb://CASTLE/Movies/We Are Your Friends.mkv
11:36:30 T:140539693541120   DEBUG: Mysql execute: update files set playCount=1,lastPlayed='2015-12-22 11:36:30' where idFile=2349
11:36:31 T:140539693541120   DEBUG: Mysql execute: delete from bookmark where idFile=2349 and type=1
11:36:31 T:140539693541120   DEBUG: Mysql execute: update settings set Deinterlace=1,ViewMode=0,ZoomAmount=1.000000,PixelRatio=1.000000,VerticalShift=0.000000,AudioStream=-1,SubtitleStream=0,SubtitleDelay=0.000000,SubtitlesOn=0,Brightness=50.000000,Contrast=50.000000,Gamma=20.000000,VolumeAmplification=0.000000,AudioDelay=0.000000,OutputToAllSpeakers=0,Sharpness=0.000000,NoiseReduction=0.000000,NonLinStretch=0,PostProcess=0,ScalingMethod=1,DeinterlaceMode=1,ResumeTime=0,StereoMode=0,StereoInvert=0 where idFile=2349
11:36:33 T:140540175100032   DEBUG: ProcessMouse: trying mouse action leftclick
11:36:33 T:140540175100032   DEBUG: Loading settings for smb://CASTLE/Movies/We Are Your Friends.mkv
11:36:33 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers(smb://CASTLE/Movies/We Are Your Friends.mkv)
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: system rules
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: mms/udp
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtmp
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtsp
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: streams
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvd
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvdimage
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: nsv
11:36:33 T:140540175100032   DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: radio
11:36:33 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: matched 0 rules with players
11:36:33 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (1)
11:36:33 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
11:36:33 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
11:36:33 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: adding player: DVDPlayer (1)
11:36:33 T:140540175100032   DEBUG: CPlayerCoreFactory::GetPlayers: added 1 players
11:36:33 T:140540175100032   DEBUG: Radio UECP (RDS) Processor - new CDVDRadioRDSData
11:36:33 T:140540175100032  NOTICE: DVDPlayer: Opening: smb://CASTLE/Movies/We Are Your Friends.mkv
11:36:33 T:140540175100032 WARNING: CDVDMessageQueue(player)::Put MSGQ_NOT_INITIALIZED
11:36:33 T:140540175100032   DEBUG: CRenderManager::UpdateDisplayLatency - Latency set to 0 msec
11:36:33 T:140540175100032   DEBUG: LinuxRendererGL: Cleaning up GL resources
11:36:33 T:140540175100032   DEBUG: CLinuxRendererGL::PreInit - precision of luminance 16 is 16
11:36:33 T:140539706377984   DEBUG: Thread DVDPlayer start, auto delete: false
11:36:33 T:140539706377984  NOTICE: Creating InputStream
11:36:33 T:140539706377984   DEBUG: CSMBFile::Open - opened smb://CASTLE/Movies/We Are Your Friends.mkv, fd=10000
11:36:33 T:140539706377984   DEBUG: ScanForExternalSubtitles: Searching for subtitles...
11:36:33 T:140539706377984   DEBUG: ScanForExternalSubtitles: END (total time: 5 ms)
11:36:33 T:140539706377984  NOTICE: Creating Demuxer
11:36:33 T:140539706377984   DEBUG: Open - probing detected format [matroska,webm]
11:36:33 T:140539706377984   DEBUG: Open - avformat_find_stream_info starting
11:36:33 T:140539706377984   DEBUG: Open - av_find_stream_info finished
11:36:33 T:140539706377984    INFO: ffmpeg[7FD1F3468700]: Input #0, matroska,webm, from 'smb://CASTLE/Movies/We Are Your Friends.mkv':
11:36:33 T:140539706377984    INFO: ffmpeg[7FD1F3468700]:   Metadata:
11:36:33 T:140539706377984    INFO: ffmpeg[7FD1F3468700]:     title           : We Are Your Friends
11:36:33 T:140539706377984    INFO: ffmpeg[7FD1F3468700]:     encoder         : libebml v1.3.1 + libmatroska v1.4.2
11:36:33 T:140539706377984    INFO: ffmpeg[7FD1F3468700]:     creation_time   : 2015-12-13 03:37:15
11:36:33 T:140539706377984    INFO: ffmpeg[7FD1F3468700]:   Duration: 01:36:03.36, start: 0.000000, bitrate: 35129 kb/s

On the first attempt, it throws the error "unix_err:'d' error : 'Permission denied'", but simply clicking it again allows it to play.

Could it be that the username & password for the SMB share are not always being sent when the movie is played, only sometimes?

The only difference I can spot in the log is this line:

Code:
11:36:30 T:140539693541120   DEBUG: CSMBFile::Open - opened smb://CASTLE/Movies/We Are Your Friends.mkv, fd=-1

Where it always seems to show "fd=-1" for the times it wont play..

Code:
11:36:33 T:140539706377984   DEBUG: CSMBFile::Open - opened smb://CASTLE/Movies/We Are Your Friends.mkv, fd=10000

.. but "fd=10000" where it does play. I'm not sure what that means?