2018-01-26, 16:54
I update my Ubuntu 16.04 system every month or so. After my update yesterday, my Kodi 17.6 system to stop playing videos. Instead I would get either no playback, or, after a long delay, the message "One or more items failed to play. Check the log...". It turns out that disabling the setting "Look for remote UPnP players" and restarting Kodi fixes the problem. It also works if you explicitly choose "VideoPlayer" in the Context Menu-> "Play from here" menu item. Choosing "(Default)" fails.
My assumption is that the problem is due to some UPnP related Ubuntu package. I'll see if I can figure out which one.
A full log is at: https://www.dropbox.com/s/pbhdbxwq4hkfbqu/kodi.log?dl=0
The following lines that look most interesting to me:
08:29:53.931 T:140715148179840 WARNING: VIDEO database configuration is experimental.
08:29:53.931 T:140715148179840 NOTICE: Default Video Player: VideoPlayer
08:29:53.931 T:140715148179840 NOTICE: Default Audio Player: paplayer
08:29:53.931 T:140715148179840 NOTICE: Enabled debug logging due to GUI setting (2)
08:29:53.931 T:140715148179840 NOTICE: Log level changed to "LOG_LEVEL_DEBUG_FREEMEM"
08:29:53.931 T:140715148179840 NOTICE: CMediaSourceSettings: loading media sources from special://masterprofile/sources.xml
08:29:53.931 T:140715148179840 DEBUG: CMediaSourceSettings: Setting <default> source to : Picture add-ons
08:29:53.931 T:140715148179840 NOTICE: Loading player core factory settings from special://xbmc/system/playercorefactory.xml.
08:29:53.931 T:140715148179840 DEBUG: CPlayerCoreConfig::<ctor>: created player VideoPlayer
08:29:53.931 T:140715148179840 DEBUG: CPlayerCoreConfig::<ctor>: created player PAPlayer
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: system rules
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: mms/udp
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: lastfm/shout
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: rtmp
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: rtsp
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: streams
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: aacp/sdp
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: mp2
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: dvd
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: dvdimage
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: sdp/asf
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: nsv
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: radio
08:29:53.931 T:140715148179840 NOTICE: Loaded playercorefactory configuration
08:29:53.931 T:140715148179840 NOTICE: Loading player core factory settings from special://masterprofile/playercorefactory.xml.
08:29:53.931 T:140715148179840 NOTICE: special://masterprofile/playercorefactory.xml does not exist. Skipping
8:30:03.375 T:140711609087744 INFO: Platinum [neptune.http]: got connection (reused: false)
08:30:03.376 T:140711609087744 NOTICE: Platinum [platinum.core.ctrlpoint]: Device "060b7353-fca6-4070-85f4-1fbfb9add62c" is now known as "Wireless Router Archer C9" (http://192.168.1.2:1900/igd.xml)
08:30:03.376 T:140711609087744 ERROR: Platinum [platinum.core.ctrlpoint]: Invalid SCPD url "://192.168.1.2:1900/l3f.xml" for service "urn:upnp-orgerviceId:L3Forwarding1" of device "Wireless Router Archer C9"!
08:30:03.376 T:140711609087744 ERROR: Platinum [platinum.core.ctrlpoint]: NPT_CHECK failed, result=-20011 (NPT_ERROR_INVALID_SYNTAX) [(res = FetchDeviceSCPDs(task, root_device, 0))]
08:30:03.474 T:140712037308160 INFO: Platinum [platinum.core.ctrlpoint]: Device "Wireless Router Archer C9" expiration time renewed..
08:30:04.839 T:140715148179840 DEBUG: OnKey: return (0xf00d) pressed, action is Select
08:30:04.841 T:140715148179840 DEBUG: OnPlayMedia /movies/XBMC/Frank/The 3 Worlds of Gulliver (1960).mkv
08:30:04.842 T:140714649208576 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:30:04.842 T:140714649208576 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:30:04.842 T:140715148179840 DEBUG: Loading settings for /movies/XBMC/Frank/The 3 Worlds of Gulliver (1960).mkv
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers(/movies/XBMC/Frank/The 3 Worlds of Gulliver (1960).mkv)
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: system rules
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: mms/udp
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtmp
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtsp
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: streams
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvd
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvdimage
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: nsv
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: radio
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: adding player: for rule: system rules
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: matched 1 rules with players
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (VideoPlayer)
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: Living Room - Sonos CONNECT Media Renderer
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: Bathroom - Sonos PLAY:1 Media Renderer
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: Bedroom - Sonos PLAY:3 Media Renderer
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: Kitchen - Sonos PLAY:3 Media Renderer
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: added 6 players
08:30:04.844 T:140715148179840 ERROR: Error creating player for item /movies/XBMC/Frank/The 3 Worlds of Gulliver (1960).mkv (File doesn't exist?)
08:30:04.844 T:140715148179840 DEBUG: OnPlayBackStopped: play state was 1, starting 0
08:30:04.844 T:140715148179840 ERROR: Playlist Player: skipping unplayable item: 0, path [/movies/XBMC/Frank/The 3 Worlds of Gulliver (1960).mkv]
08:30:04.844 T:140715148179840 DEBUG: Playlist Player: no more playable items... aborting playback
My assumption is that the problem is due to some UPnP related Ubuntu package. I'll see if I can figure out which one.
A full log is at: https://www.dropbox.com/s/pbhdbxwq4hkfbqu/kodi.log?dl=0
The following lines that look most interesting to me:
08:29:53.931 T:140715148179840 WARNING: VIDEO database configuration is experimental.
08:29:53.931 T:140715148179840 NOTICE: Default Video Player: VideoPlayer
08:29:53.931 T:140715148179840 NOTICE: Default Audio Player: paplayer
08:29:53.931 T:140715148179840 NOTICE: Enabled debug logging due to GUI setting (2)
08:29:53.931 T:140715148179840 NOTICE: Log level changed to "LOG_LEVEL_DEBUG_FREEMEM"
08:29:53.931 T:140715148179840 NOTICE: CMediaSourceSettings: loading media sources from special://masterprofile/sources.xml
08:29:53.931 T:140715148179840 DEBUG: CMediaSourceSettings: Setting <default> source to : Picture add-ons
08:29:53.931 T:140715148179840 NOTICE: Loading player core factory settings from special://xbmc/system/playercorefactory.xml.
08:29:53.931 T:140715148179840 DEBUG: CPlayerCoreConfig::<ctor>: created player VideoPlayer
08:29:53.931 T:140715148179840 DEBUG: CPlayerCoreConfig::<ctor>: created player PAPlayer
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: system rules
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: mms/udp
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: lastfm/shout
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: rtmp
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: rtsp
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: streams
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: aacp/sdp
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: mp2
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: dvd
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: dvdimage
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: sdp/asf
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: nsv
08:29:53.931 T:140715148179840 DEBUG: CPlayerSelectionRule::Initialize: creating rule: radio
08:29:53.931 T:140715148179840 NOTICE: Loaded playercorefactory configuration
08:29:53.931 T:140715148179840 NOTICE: Loading player core factory settings from special://masterprofile/playercorefactory.xml.
08:29:53.931 T:140715148179840 NOTICE: special://masterprofile/playercorefactory.xml does not exist. Skipping
8:30:03.375 T:140711609087744 INFO: Platinum [neptune.http]: got connection (reused: false)
08:30:03.376 T:140711609087744 NOTICE: Platinum [platinum.core.ctrlpoint]: Device "060b7353-fca6-4070-85f4-1fbfb9add62c" is now known as "Wireless Router Archer C9" (http://192.168.1.2:1900/igd.xml)
08:30:03.376 T:140711609087744 ERROR: Platinum [platinum.core.ctrlpoint]: Invalid SCPD url "://192.168.1.2:1900/l3f.xml" for service "urn:upnp-orgerviceId:L3Forwarding1" of device "Wireless Router Archer C9"!
08:30:03.376 T:140711609087744 ERROR: Platinum [platinum.core.ctrlpoint]: NPT_CHECK failed, result=-20011 (NPT_ERROR_INVALID_SYNTAX) [(res = FetchDeviceSCPDs(task, root_device, 0))]
08:30:03.474 T:140712037308160 INFO: Platinum [platinum.core.ctrlpoint]: Device "Wireless Router Archer C9" expiration time renewed..
08:30:04.839 T:140715148179840 DEBUG: OnKey: return (0xf00d) pressed, action is Select
08:30:04.841 T:140715148179840 DEBUG: OnPlayMedia /movies/XBMC/Frank/The 3 Worlds of Gulliver (1960).mkv
08:30:04.842 T:140714649208576 DEBUG: CAnnouncementManager - Announcement: OnAdd from xbmc
08:30:04.842 T:140714649208576 DEBUG: GOT ANNOUNCEMENT, type: 2, from xbmc, message OnAdd
08:30:04.842 T:140715148179840 DEBUG: Loading settings for /movies/XBMC/Frank/The 3 Worlds of Gulliver (1960).mkv
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers(/movies/XBMC/Frank/The 3 Worlds of Gulliver (1960).mkv)
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: system rules
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: matches rule: system rules
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: mms/udp
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: lastfm/shout
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtmp
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: rtsp
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: streams
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvd
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: dvdimage
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: sdp/asf
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: nsv
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: considering rule: radio
08:30:04.844 T:140715148179840 DEBUG: CPlayerSelectionRule::GetPlayers: adding player: for rule: system rules
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: matched 1 rules with players
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: adding videodefaultplayer (VideoPlayer)
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=0
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: for video=1, audio=1
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: Living Room - Sonos CONNECT Media Renderer
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: Bathroom - Sonos PLAY:1 Media Renderer
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: Bedroom - Sonos PLAY:3 Media Renderer
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: adding player: Kitchen - Sonos PLAY:3 Media Renderer
08:30:04.844 T:140715148179840 DEBUG: CPlayerCoreFactory::GetPlayers: added 6 players
08:30:04.844 T:140715148179840 ERROR: Error creating player for item /movies/XBMC/Frank/The 3 Worlds of Gulliver (1960).mkv (File doesn't exist?)
08:30:04.844 T:140715148179840 DEBUG: OnPlayBackStopped: play state was 1, starting 0
08:30:04.844 T:140715148179840 ERROR: Playlist Player: skipping unplayable item: 0, path [/movies/XBMC/Frank/The 3 Worlds of Gulliver (1960).mkv]
08:30:04.844 T:140715148179840 DEBUG: Playlist Player: no more playable items... aborting playback