Unexpected behaviour in ElasticsearchTestCase when querying too soon after initialization.

[mindaugasbarysas]

Consider the following code:

/**
 * Demonstrates unexpected behaviour of ElasticsearchTestCase.
 */
class ESBProblem extends ElasticsearchTestCase {

    /**
     * Test for success - succeeds.
     */
    public function testSuccess()
    {
        $repository=$this->getManager()->getRepository('AcmeTestBundle:Product');
        usleep(250000);
        $repository->execute($repository->createSearch());
    }

    /**
     * Test for fail - fails.
     *
     * @expectedException \Exception
     */
    public function testFail()
    {
        $repository=$this->getManager()->getRepository('AcmeTestBundle:Product');
        // Let's remove usleep(250000) and see what happens.
        $repository->execute($repository->createSearch());
    }
} 

[martiis]

Just tried it with latest ONGRTestingBundle and ESB, everything works without exceptions.

Maybe your client or java needs an update or try to reinstall.

[mindaugasbarysas]

PHPUnit data coverage logging must be off. Since this seems to be a timing-related bug, milliseconds make a difference.

[mindaugasbarysas]

This seems to be a problem with ES itself:

vagrant@testvm:/var/www$ echo "";i=0; while [[ "$i" != "10" ]]; do curl -s -XDELETE 'localhost:9200/test'; curl -s -XPUT 'localhost:9200/test'; curl -XGET 'localhost:9200/test/_search/'; echo " "; i=`expr $i + 1`; done

{"acknowledged":true}{"acknowledged":true}{"took":1,"timed_out":false,"_shards":{"total":5,"successful":1,"failed":0},"hits":{"total":0,"max_score":null,"hits":[]}} 
{"acknowledged":true}{"acknowledged":true}{"took":0,"timed_out":false,"_shards":{"total":5,"successful":3,"failed":0},"hits":{"total":0,"max_score":null,"hits":[]}} 
{"acknowledged":true}{"acknowledged":true}{"took":0,"timed_out":false,"_shards":{"total":5,"successful":3,"failed":0},"hits":{"total":0,"max_score":null,"hits":[]}} 
{"acknowledged":true}{"acknowledged":true}{"took":1,"timed_out":false,"_shards":{"total":5,"successful":1,"failed":0},"hits":{"total":0,"max_score":null,"hits":[]}} 
{"acknowledged":true}{"acknowledged":true}{"took":0,"timed_out":false,"_shards":{"total":5,"successful":3,"failed":0},"hits":{"total":0,"max_score":null,"hits":[]}} 
{"acknowledged":true}{"acknowledged":true}{"took":0,"timed_out":false,"_shards":{"total":5,"successful":3,"failed":0},"hits":{"total":0,"max_score":null,"hits":[]}} 
{"acknowledged":true}{"acknowledged":true}{"error":"SearchPhaseExecutionException[Failed to execute phase [query], all shards failed]","status":503} 
{"acknowledged":true}{"acknowledged":true}{"took":1,"timed_out":false,"_shards":{"total":5,"successful":2,"failed":0},"hits":{"total":0,"max_score":null,"hits":[]}} 
{"acknowledged":true}{"acknowledged":true}{"error":"SearchPhaseExecutionException[Failed to execute phase [query], all shards failed]","status":503} 
{"acknowledged":true}{"acknowledged":true}{"error":"SearchPhaseExecutionException[Failed to execute phase [query], all shards failed]","status":503} 
vagrant@testvm:/var/www$ echo "";i=0; while [[ "$i" != "10" ]]; do curl -s -XDELETE 'localhost:9200/test'; curl -s -XPUT 'localhost:9200/test'; curl -XGET 'localhost:9200/test/_search/'; echo " "; i=`expr $i + 1`; done

{"acknowledged":true}{"acknowledged":true}{"error":"SearchPhaseExecutionException[Failed to execute phase [query], all shards failed]","status":503} 
{"acknowledged":true}{"acknowledged":true}{"error":"SearchPhaseExecutionException[Failed to execute phase [query], all shards failed]","status":503} 
{"acknowledged":true}{"acknowledged":true}{"error":"SearchPhaseExecutionException[Failed to execute phase [query], all shards failed]","status":503} 
{"acknowledged":true}{"acknowledged":true}{"took":0,"timed_out":false,"_shards":{"total":5,"successful":1,"failed":0},"hits":{"total":0,"max_score":null,"hits":[]}} 
{"acknowledged":true}{"acknowledged":true}{"took":0,"timed_out":false,"_shards":{"total":5,"successful":3,"failed":0},"hits":{"total":0,"max_score":null,"hits":[]}} 
{"acknowledged":true}{"acknowledged":true}{"error":"SearchPhaseExecutionException[Failed to execute phase [query], all shards failed]","status":503} 
{"acknowledged":true}{"acknowledged":true}{"error":"SearchPhaseExecutionException[Failed to execute phase [query], all shards failed]","status":503} 
{"acknowledged":true}{"acknowledged":true}{"error":"SearchPhaseExecutionException[Failed to execute phase [query], all shards failed]","status":503} 
{"acknowledged":true}{"acknowledged":true}{"error":"SearchPhaseExecutionException[Failed to execute phase [query], all shards failed]","status":503} 
{"acknowledged":true}{"acknowledged":true}{"error":"SearchPhaseExecutionException[Failed to execute phase [query], all shards failed]","status":503} 

may I propose a delay of a few milliseconds after https://github.com/ongr-io/ElasticsearchBundle/blob/master/Test/ElasticsearchTestCase.php#L161 as a solution?

[martiis]

I noticed few tests sometimes fails in travis with service unavailable or all shard failed response, but we can live with that currently. Delay is rarely a good solution :)

[mindaugasbarysas]

alternative would be catching this particular exception and retrying, these guys (https://www.devmynd.com/blog/2014-2-dealing-with-failing-elasticserach-tests) seem to have solved this exact problem in the same fashion.

[martiis]

I like it. I'll investigate how can we achieve this.