"SolrServerException: No solr server available." in version 1.3.x

[fralken]

Hello, I'm using SolrCLoud with Zookeeper and I'm initializing an AsyncSolrClient like this:

val serversSolr = new CloudSolrServers(
    zkHost = play.Play.application.configuration.getString("solr.zk"),
    defaultCollection = Some(play.Play.application.configuration.getString("solr.collection")))

val solr = AsyncSolrClient.Builder(RoundRobinLB(serversSolr)).build

The first time I execute a call like this:

...
solr.query(myquery)
...

I get the following exception:

org.apache.solr.client.solrj.SolrServerException: No solr server available.
    at io.ino.solrs.AsyncSolrClient.io$ino$solrs$AsyncSolrClient$$loadBalanceQuery(AsyncSolrClient.scala:199) ~[solrs_2.11-1.3.1.jar:1.3.1]
    at io.ino.solrs.AsyncSolrClient.query(AsyncSolrClient.scala:178) ~[solrs_2.11-1.3.1.jar:1.3.1]

If I execute the same query again, everything works fine. Apparently the problem doesn't happen if just after the creation of the AsyncSolrClient I call this:

serversSolr.setAsyncSolrClient(solr)

In version 1.2.0 and previous versions everything works fine.
Thanks

[andreaTP]

👍

[magro]

Strange: I'd say that this is caused by the warmup queries (see also commit f97c402) - but as it seems you don't set warmupQueries on the CloudSolrServers. Can you please double check that you're not setting warmupQueries?

[andreaTP]

Confirmed:
warmupQueries is not setted

[magro]

Just looking into this, and I cannot reproduce this (in our application) with the setup code you posted.
What I find really weird is that you write that serversSolr.setAsyncSolrClient(solr) fixes the problem for you - which is already done by AsyncSolrClient.Builder.build: https://github.com/inoio/solrs/blob/master/src/main/scala/io/ino/solrs/AsyncSolrClient.scala#L96

Looking further into this...

[magro]

Btw, does it matter how much time is spent after the creation of the AsyncSolrClient instance before you call solr.query(myquery) the first time?

[magro]

Assuming you have set the log level for "io.ino.solrs" to INFO, (when) do you see the log message "Connected to zookeeper at ", and how does it change if you additionally call serversSolr.setAsyncSolrClient(solr)?

[fralken]

It doesn't metter how long I wait after creation of AsyncSolrClient and the first call to solr.query(myquery).

Without yhe additional call I have the following log:

[info] play - Application started (Dev)
[info] i.i.s.CloudSolrServers - Connected to zookeeper at ...
[info] i.i.s.CloudSolrServers - Successfully created ZK cluster state watchers at ...
[error] play - Cannot invoke the action, eventually got an error: org.apache.solr.client.solrj.SolrServerException: No solr server available.
...
...
[info] i.i.s.CloudSolrServers - Updated server map: ...

When adding the additional call serversSolr.setAsyncSolrClient(solr)I have:

[info] play - Application started (Dev)
[info] i.i.s.CloudSolrServers - Connected to zookeeper at ... 
[info] i.i.s.CloudSolrServers - Successfully created ZK cluster state watchers at ...
[info] i.i.s.CloudSolrServers - Connected to zookeeper at ...
[info] i.i.s.CloudSolrServers - Updated server map: ...

As you can see, the Connected to zookeeper atappears twice this time, and the first query is succesful.

[fralken]

Ok, it appears in my code that the AsyncSolrClient is actually initialized just before the first solr.query(). Since I see the "update server map" is scheduled to run after 1 second, that is why I get "no solr servers available". If I force in some ways the initialization of AsyncSolrClient and then wait before the first solr.query(), it works fine.

Maybe it could be convenient in initZkStateReader to invoke updateFromClusterState once before scheduling for execution, so that we are sure the state of the client is consistent as soon as it is created.

[magro]

Thanx for the log extracts! Can you also set the log level for org.apache.solr.common.cloud to INFO, please? It would also be helpful to have timestamps there as well.

Re updateFromClusterState: this is scheduled with initialDelay=0 (https://github.com/inoio/solrs/blob/master/src/main/scala/io/ino/solrs/SolrServers.scala#L139), so it should be invoked right away - only the thread creation time is added. We could also add debug log statements to updateFromClusterState to debug this.

[fralken]

I agree that initialDelay=0 but for some reason it is not executed as soon as it is scheduled

[fralken]

I added log level INFO for org.apache.solr.common.cloud...

[info] play - Application started (Dev)
[info] o.a.s.c.c.SolrZkClient - Using default ZkCredentialsProvider
[info] o.a.s.c.c.ConnectionManager - Waiting for client to connect to ZooKeeper
[info] o.a.s.c.c.ConnectionManager - Watcher org.apache.solr.common.cloud.ConnectionManager@2526db49 name:ZooKeeperConnection Watcher:... got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[info] o.a.s.c.c.ConnectionManager - Client is connected to ZooKeeper
[info] o.a.s.c.c.SolrZkClient - Using default ZkACLProvider
[info] i.i.s.CloudSolrServers - Connected to zookeeper at ...
[info] o.a.s.c.c.ZkStateReader - Updating cluster state from ZooKeeper... 
[info] i.i.s.CloudSolrServers - Successfully created ZK cluster state watchers at ...
[error] play - Cannot invoke the action, eventually got an error: org.apache.solr.client.solrj.SolrServerException: No solr server available.

[andreaTP]

with akka scheduled jobs are executed asynchronously and execution time is not strongly guaranteed.
Moreover:
https://github.com/akka/akka/blob/67ca6e5dc70509d279a005763a30fb0bd7c871df/akka-actor/src/main/scala/akka/actor/Scheduler.scala#L299

so 0 delay means an interval 0 > T < (1/maxFrequency)

[andreaTP]

here is the reference (yellow box:
http://doc.akka.io/docs/akka/2.3.4/scala/scheduler.html
)

[fralken]

In initZkStateReaderyou could initialize the update like this:

  // Now regularly update the server list from ZkStateReader clusterState
  updateFromClusterState(zkStateReader)
  scheduledExecutor.scheduleAtFixedRate(new Runnable {
    override def run(): Unit = updateFromClusterState(zkStateReader)
  }, clusterStateUpdateInterval.toMillis, clusterStateUpdateInterval.toMillis, TimeUnit.MILLISECONDS)

so that the first execution is guaranteed to be synchronus, and then the other are scheduled to be executed starting after the desired interval

[magro]

I just changed it like this, its as version 1.3.2 on its way to maven central. Does this work for you?

[fralken]

Yes, it works. Thanks.

[magro]

Great!

[andreaTP]

tnx!