2015-12-22, 06:15
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:
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:
Where it always seems to show "fd=-1" for the times it wont play..
.. but "fd=10000" where it does play. I'm not sure what that means?
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:PASSWORD@CASTLE/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/sOn 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=-1Where 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?
