Created attachment 2275 [details]
server.log after startup when the problem occurs

This is the server.log file after startup when the problem occurs, you should be able to see the times in the log.

I guess we could blame the plugins, but I think SqueezeServer should be able to handle plugins that needs to do some stuff that takes a few seconds at SqueezeServer startup.

it's probably not plugin relates.  Squeezenetwork is seeing some timeouts for certain regions.  Upgrades are in progress.

(In reply to comment #2)
> it's probably not plugin relates.  Squeezenetwork is seeing some timeouts for
> certain regions.  Upgrades are in progress.
> 

Well I think it is, because if I disable some of my plugins it works perfectly and 
when I enable them again directly afterwards and restart SqueezeCenter I get the message. 
It's very easy to reproduce on my machine, with only standard plugins which start pretty quick
everything works as it should, with my own plugins enabled which take a bit longer to startup
it fails.

Maybe the SqueezeNetwork requests are started before the plugins are loaded  and then 
it loads the plugin and if that takes to much time, the SqueezeNetwork request timeout 
even if SqueezeNetwork really is available ?

Then you'll need to add more debug options.  Those logs show nothing other than SN timeouts.
Perhaps there is one that is making a blocked connection, try narrowing it down.

Created attachment 2293 [details]
server.log file with some more debugging enabled

I enabled the network.* and server.* debugging flags in this server.log file, let me know if you want me to enable some other flags.

Thanks Erland,

did you do this with the latest from SVN.  I saw that Andy added a number of dns related changes on friday, so that might have an effect here.

(In reply to comment #6)
> Thanks Erland,
> 
> did you do this with the latest from SVN.  I saw that Andy added a number of
> dns related changes on friday, so that might have an effect here.
> 

The latest log attached was with svn 13941

Yes there are some async requests started during init that are not processed until later, so they can time out if other init things take too long.  Perhaps anything in init should be started by a timer instead so they don't run until after init.  I'll look at this.

Should be fixed in change 13984.

This correction didn't solve the problem for me, the problem remains in my setup. I tried to make a sample plugin that just made a sleep in it's initPlugin, but I wasn't able to reproduce the problem this way so I'm not sure exactly what the problem is.

Created attachment 2299 [details]
server.log file from svn #13997

Can you trim down your debug settings to only include network.asynchttp?  There's too much junk to sort out what your problem is.

Created attachment 2301 [details]
server.log with only network.asynchttp = DEBUG

Hmm, are you sure you are running the very latest code?  These:

[19:02:28.2971] Slim::Networking::SimpleAsyncHTTP::_createHTTPRequest (105) GETing http://update.slimdevices.com/update/firmware/7.0/jive.version
[19:02:28.3046] Slim::Networking::SimpleAsyncHTTP::_createHTTPRequest (105) GETing http://www.squeezenetwork.com/api/v1/time

Should now not occur until after "SqueezeCenter done init".

Check the file Slim::Networking::SqueezeNetwork and look for this in init():

        # Any async HTTP in init must be done on a timer
        Slim::Utils::Timers::setTimer(
                undef,  
                time(),
                sub {
                        $http->get( $timeURL );
                },
        ); 

(In reply to comment #14)
> Should now not occur until after "SqueezeCenter done init".
> 
> Check the file Slim::Networking::SqueezeNetwork and look for this in init():
> 
>         # Any async HTTP in init must be done on a timer
>         Slim::Utils::Timers::setTimer(
>                 undef,  
>                 time(),
>                 sub {
>                         $http->get( $timeURL );
>                 },
>         ); 
> 

I'm running svn 13997, and that code exist in the end of the init() function in Slim::Networking::SqueezeNetwork

Hmm, do any of those 3rd party plugins call idle() or idleStreams() during init?

(In reply to comment #16)
> Hmm, do any of those 3rd party plugins call idle() or idleStreams() during
> init?
> 

Yes, one of them calls idleStreams. But I tried to remove those calls and the SqueezeNetwork and jive connections still fails. However, I also tested to insert a log message in the idleStreams function and it seems that it is still called indirectly because the plugin also calls Slim::Utils::Misc::readDirectory which calls idleStreams.

I can reproduce the problem with a simple sample plugin that sleeps a bit and calls idleStreams during initialization.

Created attachment 2302 [details]
Sample plugin that can be used to reproduce the problem.

OK, guess I need to find another way around this.  Probably will create a flag for "init mode" and have idle and idleStreams be a noop during init.

OK I think it should really be fixed this time. :)  Change 14014.

I'm sorry, but it still doesn't work. I think the problem is that I do some operations in initPlugin but I also call Slim::Utils::Scheduler::add_task at the end of initPlugin because some operations can't be executed until all plugins have been loaded. It seems like your fix corrects the case when idleStreams are called within initPlugin, but it doesn't cover the case when it's called with in the function specified in add_task.

Created attachment 2303 [details]
Updated sample plugin that reproduces the problem with an add_task call

But nothing in Scheduler is run until after init is done so this should not be a problem.  Putting a sleep in a scheduled task is just stupid!  Are your plugins blocking the server for a large amount of time after init?  If so, why?  You should only block during the init phase (or only do it with a child process i.e. scanner.pl).

I need to do some things after initPlugin beacuse there are dependencies to other plugins. So if I call PluginManager->enabledPlugins inside initPlugin I won't get all plugins, but if I call it inside the function specified with add_task it works because then it isn't executed until all plugins have been loaded.

The operations executed are some XML parsing and some database table updates. The operations executed in the add_task function might take a few seconds, maybe maximum 10 seconds.

The sample plugin I attached is a bit extreme in that it sleeps for 20 seconds during initPlugin and 20 seconds after initPlugin, the times are shorter in the real plugins.

There is nothing I can do if plugins are going to block for that amount of time.  I still consider this issue fixed.

Also, I was just looking at your CustomBrowse plugin.  Please don't perform synchronous HTTP requests within SC (using SOAP::Lite, etc).  You should avoid blocking the server at all costs.