RPi2 with RC2 and 3: Add-Ons not downloading (NOT a DNS problem) [solved]

First off all: Thanks for this beautiful product!

But than: I have installed both RC2 and RC3 multiple times on a (fresh) SDcard. OSMC starts and I (seem to) be able to change all kinds of settings. Once I was even able to install the Weathermap.
When I try to install Add-Ons I select “Install” than for a view seconds there is no response and than the system goes up one menu (to the “list of add-ons”). Beneath the selected add-on (for example YouTube) is a line “Downloading 0%”. I see a “Busy” pop up a view times and then the “Downloading 0%” message disappear. If I select the “Updatelog” option (not sure what it’s called, I’m not at home) there is one line “Downloading”. Nothing more.
Most important: The Add-On is not installed!!

  • Raspberry Pi 2B
  • Updating the system seems to work as there is a lot of downloading and installing and a restart
  • I do have internet access from the OSMC RPi as I can “ping” to sites on the internet.
  • Created the SDcard with the OSX install app
  • I was able to select (install?) an other skin

Also:

  • I do have CCurlFile “Stat - Failed: Timeout was reached(28)” error messages in the log.
  • I don’t have CCurlFile “Stat - Failed: Couldn’t connect to server” messages
  • Manual entering curl will however download the zip file and pictures as in an other post about this problem.
  • Checked /etc/connman.prefs and “dnsproxy=no” (was already so)

We’re going to need full debug logs to get any idea of what is going on here.

First make sure you have run updates as there are quite a number of updates post-RC3.

Can you then enable debugging in Kodi, reboot, and try to reproduce your problems (failed addon install) then use the log uploader to upload full logs ? If the log uploader can’t upload for some reason you could use the save to SD card option which will save the log files on the fat32 partition on the SD card so you can retrieve them on a PC.

If you’re seeing a curl timeout it does suggest a connectivity problem to the server hosting the addon - the timeout is 30 seconds by default which means no data was received from the server for 30 seconds, which is a long time…

Hello DBMandrake,

Thanks for your reply.
I now have the kodi.old.log on my PC, how can I get it in a place for you to see/read?

kodi.old.log is not a full debug log - the log uploader also gathers other system configuration and logs such as the system journal which are important to help diagnose a network connectivity issue, so please try again with the log uploader. I don’t recall exactly what the file name is that it saves as but it’s not kodi.old.log. (This is only a Kodi log by itself)

You can upload logs from your PC by pasting them here:

http://paste.osmc.io/

1 Like

As I am not at home I have placed the kodi.old.log on the URL you gave me. This is the reply (I think) I got after saving “http://paste.osmc.io/dodahexuvu.coffee”.

Also uploaded the output from journalctl: “http://paste.osmc.io/iquwaxodoc.vhdl

Tonight I will create the logs as you asked for. Hope you can already “see” something from the kodi log…

Anyway: Thanks again for your help.

All I can really tell from that log is that there are hundreds of curl timeouts when trying to download files from mirrors.kodi.tv, which suggests a network connectivity problem. Hopefully your full logs will show something.

Are you using Ethernet or Wifi ? If Wifi can you test with Ethernet ?

I’m using Ethernet. Still, strange that uploading those files (I tested YouTube) from the command-line does not have a problem…

For your information, this test:

wget -O /dev/null http://speedtest.wdc01.softlayer.com/downloads/test10.zip

Shows a downloadspeed of 2.32MB/s

Downloading plugin.video.youtube-5.1.5.zip:

converted 'http://mirrors.kodi.tv/addons/helix/plugin.video.youtube/plugin.video.youtube-5.1.5.zip' (ANSI_X3.4-1968)
    -> 'http://mirrors.kodi.tv/addons/helix/plugin.video.youtube/plugin.video.youtube-5.1.5.zip' (UTF-8)
--2015-06-04 13:01:41--  http://mirrors.kodi.tv/addons/helix/plugin.video.youtube/plugin.video.youtube-5.1.5.zip
Resolving mirrors.kodi.tv (mirrors.kodi.tv)... 89.16.176.16
Connecting to mirrors.kodi.tv (mirrors.kodi.tv)|89.16.176.16|:80... connected.
HTTP request sent, awaiting response... 302 Found
Location: http://mirror.nl.leaseweb.net/xbmc/addons/helix/plugin.video.youtube/plugin.video.youtube-5.1.5.zip [following]
converted 'http://mirror.nl.leaseweb.net/xbmc/addons/helix/plugin.video.youtube/plugin.video.youtube-5.1.5.zip' (ANSI_X3.4-1968) 
    -> 'http://mirror.nl.leaseweb.net/xbmc/addons/helix/plugin.video.youtube/plugin.video.youtube-5.1.5.zip' (UTF-8)
--2015-06-04 13:01:57--  http://mirror.nl.leaseweb.net/xbmc/addons/helix/plugin.video.youtube/plugin.video.youtube-5.1.5.zip
Resolving mirror.nl.leaseweb.net (mirror.nl.leaseweb.net)... 94.75.223.121
Connecting to mirror.nl.leaseweb.net (mirror.nl.leaseweb.net)|94.75.223.121|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 534726 (522K) [application/zip]
Saving to: '/dev/null'

     0K .......... .......... .......... .......... ..........  9% 2.29M 0s
      ... (more lines)
   500K .......... .......... ..                              100% 4.39M=0.2s

2015-06-04 13:02:02 (3.37 MB/s) - '/dev/null' saved [534726/534726]

Hope this helps bringing light into my darkness…
More tonight!

Ok, here’s the complete log (I hope)

http://paste.osmc.io/likuxunuxi.vhdl
  • I created a new SDcard with OSX
  • Updated via the OSMC menu (twice).
  • Then I tried to install Add-On youtube
  • Then I tried to install Add-On TED-Talks

If anything is missing, please tell me.
Thanks for the effort!

… in the mean time I have downloaded the youtube plug-in (wget) as a zip file (I copied the URL from the log). Installing the youtube plug-in from the zip file worked ‘as expected’. Viewing a NASA feed seems to work but is incredibly slow and has long hick-ups after every view seconds…

What this proves is that there does not seem to be a DNS or Ethernet problem, as the download of the zip file worked (fast! Also see my previous reply’s).
I can download (part of) the kodi.log to investicate what happens during playing the NASA video… if you need it.

Well, I do hope you can find a solution for this problem as the overall look-and-feel of OSMC is amazing!

I hate to say it, but there really is something wrong with your Internet connection to the Pi.

There is really very little to go on in your log but there are two clues that point towards internet connectivity problems:

Start-Date: 1970-01-01  00:06:49
Commandline: apt-get -o APT::Status-Fd=4 -o APT::Keep-Fds::=5 -o APT::Keep-Fds::=6 -f -y dist-upgrade
Install: rbp2-armmem-osmc:armhf (1.0.0-8, automatic), eject:armhf (2.1.5+deb1+cvs20081104-13.1, automatic)
Upgrade: tzdata:armhf (2015c-1, 2015d-0+deb8u1), fuse:armhf (2.9.3-15+b1, 2.9.3-15+deb8u1), rbp-bootloader-osmc:armhf (1.0.3-0, 1.0.4-0), libfuse2:armhf (2.9.3-15+b1, 2.9.3-15+deb8u1), rbp2-mediacenter-osmc:armhf (14.2.0-15, 14.2.0-16), mediacenter-addon-osmc:armhf (2.9.95, 2.9.991), ntfs-3g:armhf (2014.2.15AR.2-1, 2014.2.15AR.2-1+deb8u2), rbp2-device-osmc:armhf (1.1.0, 1.2.0), diskmount-osmc:armhf (1.2.5, 1.2.9)
End-Date: 1970-01-01  00:10:54

At the time this update was run the date was 1970 - this is the default date when the Pi is turned on as it has no real time clock to keep the time when turned off. So we run an ntp client that automatically tries to set the time as soon as there is a network connection. The fact that the time was incorrect by the time you ran updates means that this ntp connection on UDP port 123 was not successful at all, so that’s your first evidence of partial network connectivity problems.

Jun 04 17:34:28 osmc http-time[262]: Unable to set time using HTTP query - no response received from servers.

In a recent update (I don’t recall exactly when or whether it was in before RC3) we added a new boot service called http-time - this is a backup method of setting the time in addition to ntp. We added this because a small percentage of people can’t use ntp because their router (or possibly ISP) blocks UDP packets with a source and destination port of 123, thus they would not get the time set on their system.

So this service attempts to perform a standard HTTP get request to www.google.com, www.apple.com and www.microsoft.com in that order until it gets a connection. You can see the script that does this here:

It’s a relatively straight forward script - it first waits (up to a maximum of 60 seconds) until connman reports that the internet connection is up (which connman itself determines based on contacting a specific server on the internet) and then attempts to make an HTTP query to those three servers in order until it gets a response, with a 4 second timeout for each server.

The entry in your log clearly shows that even though connman was able to connect to its own test server and thus establish that there was some internet connectivity, three different wget attempts to three different well known websites failed.

So I can’t see how it can be anything other than an internet connectivity problem. It’s not a complete lack of connectivity otherwise connman would have never reported that the connection was up, in which case the log would have said “No internet connection was available within 60 seconds, giving up.”.

But there is definitely a problem with your connectivity from everything that I can see, as that http-time script should be very reliable.

PS I would be interested to see what output you get from the following command on your Pi:

LANG=C wget --server-response --timeout=4 --max-redirect 0 --spider www.google.com

Here is what I get, and you can see the Date: field which the script is looking for:

osmc@rpi2:~$ wget --server-response --timeout=4 --max-redirect 0 --spider www.google.com
converted 'http://www.google.com' (ANSI_X3.4-1968) -> 'http://www.google.com' (UTF-8)
Spider mode enabled. Check if remote file exists.
--2015-06-05 09:54:12--  http://www.google.com/
Resolving www.google.com (www.google.com)... 216.239.32.20
Connecting to www.google.com (www.google.com)|216.239.32.20|:80... connected.
HTTP request sent, awaiting response...
  HTTP/1.0 302 Moved Temporarily
  Cache-Control: private
  Content-Type: text/html; charset=UTF-8
  Location: http://www.google.co.uk/?gfe_rd=cr&ei=tGNxVYuwMIyCaMrlgcgC
  Content-Length: 259
  Date: Fri, 05 Jun 2015 08:54:12 GMT
  Server: GFE/2.0
  X-Cache: MISS from netpilot2.staloysius.local
  Connection: keep-alive
Location: http://www.google.co.uk/?gfe_rd=cr&ei=tGNxVYuwMIyCaMrlgcgC [following]
converted 'http://www.google.co.uk/?gfe_rd=cr&ei=tGNxVYuwMIyCaMrlgcgC' (ANSI_X3.4-1968) -> 'http://www.google.co.uk/?gfe_rd=cr&ei=tGNxVYuwMIyCaMrlgcgC' (UTF-8)
0 redirections exceeded.

Thanks again.

Seems strange to me. The time on this RPi is correct set (by what I wonder?).
I have multiple devices connected to the same switch (also 2 other RPi’s) They all work flawless (‘Pi Musicbox spotify server’, Apple TV).
Downloading files from the same URL’s as OSMC does, have no problem. Speed also is up to par.
Downloading and installing the updates worked OK.

I do see that the http-time script returns the “No response received from servers”. If I edit the file to " --timeout=6" I do get the right time so there is absolutely ‘something’ slowing down the connection…

Still. I cannot see what’s wrong here. Will try an other RPi this weekend and also try OpenElec.

In the file “/etc/resolv.conf” there is an entry for my fibreglass router-ip as nameserver. I have removed that nameserver and restored the “–timeout=6” to “4” again. If I run the http-time script it now has an instantaneous response! Much (much!!) faster than with that nameserver inserted… I will try the inpact of this as soon as I’m home…

Keep you posted.

Regards,
Willem

Possibly you have very slow DNS resolution - is it possible that your Primary DNS is slow or not responding thus it’s having to query your secondary DNS all the time ? (After a delay)

You can run sudo /usr/bin/http-time directly from the command line btw as a test without having to reboot and check logs. (Keep in mind that dns responses will be cached for a period of time though)

What dns servers do you have allocated in /etc/resolv.conf - are they your ISP’s or do they point at your router ?

Try setting Google DNS as your dns servers in OSMC (you’ll need to set a static IP as well to do that) to see if that makes any difference.

Another thing you could try is try re-enabling the dns proxy in connman - we disabled it in a recent update as it was causing a few users issues, but it may actually be helpful in the case of a slow dns server as it does it’s own local caching. To do this edit /etc/connman.prefs, change dnsproxy to yes, then reboot.

Yes,

That seems to be the problem. My primairy DNS is my Cisco router, if he can’t resolve it will go to the DNS’s off my ISP. I have removed the nameserver line pointing to my Cisco router and than http-time response is almost instantaneously, as I explained in my previous reply.

When I’m home I will see what impact this has on the OSMC server. If that solves my problems I will redesign my network and remove the DNS on my Cisco router out of the equation.

I will report back!

Thanks again for your help!!!

Great - let us know how you get on.

Just so you’re aware - manually editing /etc/resolv.conf will only last until the next time the interface comes up, at which point connman will overwrite it again. If you do need to manually configure your resolv.conf on OSMC you’d need to do that either via connmanctl or the network GUI by setting up a fully static configuration.

Edit: looks like connmanctl will allow you to override the DNS manually but still use DHCP for the rest, for example within connmanctl:

config ethernet_b827ebd04564_cable --nameservers 8.8.8.8 8.8.4.4

Replace ethernet_b827ebd04564_cable with the name of your ethernet interface found from the services command. This change will persist across reboots.

This override functionality isn’t currently available from the GUI where you’d have to go for a fully static configuration. (The GUI will correctly display the change made through connmanctl though)

Hi DBMandrake,

Yes, the problem was the bad resolution of the DNS configuration in my network. I have removed the nameserver to my Cisco router and now OSMC shows it full potential. Which is great!!!

As said before, I will change my network setup so DHCP won’t use/set my router as nameserver anymore.

Never thought the local DNS was so slow it would influence the response of my internet connection that much!!!

Thanks for all your help!

Keep up the good work.

Ironic that it actually was a DNS problem huh?
:wink:

Yes! I kind’e suppose it is!
Just the fact that you can resolve URL’s does not garentee that this happens in due time … that’s where my asumptions were wrong …
Glad it is solved now.