Error on ArangoDB upgrade to 2.4

[realsurfer]

Hi,

I just upgraded arangodb from 2.3 to 2.4 and I am getting errors from my php scripts now:

triagens\ArangoDb\ClientException: Got an invalid response from the server triagens\ArangoDb\ConnectException: Connection refused

I am using ArangoDB-PHP 2.2, is this the problem? Do I need to upgrade to the 2.4 branch or is the master branch enough?

Thanks!

[jsteemann]

I think Connection refused means that the PHP driver could not make a connection to arangod. If you are using arangod with default configuration, it will bind to 127.0.0.1:8529 since 2.4.

If your PHP client is on a different server and tries to access the remote 2.4, this will not work. To fix this, please adjust the server configuration (--server.endpoint option on the command-line when starting arangod manually or endpoint in the [server] of arangod.conf when starting it as a daemon) so arangod binds to either 0.0.0.0:8529 or the server's public IP address.

This should make this problem go away. You can also switch to the 2.3 or 2.4 version of the driver, but I guess the main problem is that it won't connect because of the server configuration.

[realsurfer]

Thanks for your reply!

Yes I saw this listed in the changes but my stack is on the same server and my config in php is set to "tcp://127.0.0.1:8529" so it should be compatible with the new default setting? Or maybe I have misunderstood?

I am able to access the web panel just fine.

[jsteemann]

Yes, that configuration should work from the PHP side of things, provided the server is also bound to tcp://127.0.0.1:8529 or tcp://0.0.0.0:8529. If so, you should also be able to access arangod via curl when on the server: curl -X GET http://127.0.0.1:8529/_api/version. This should respond with HTTP 200 (when no authentication is used), or HTTP 401 (when using authentication).

It's hard to tell from here what else could cause Connection refused. At least it's not a message coded in the PHP driver but probably from the fsockopen() function call in it. So if you could validate that the server is actually running and accessible on the IP/port configured for your PHP, that would rule a few problems out already. If the server can be connected using IP/port, you can try using the 2.3 or 2.4 of the driver. I have also upgraded the master branch to 2.3 if you prefer that.

[realsurfer]

I ran the curl request and got {"server":"arango","version":"2.4.1"}. I will try and upgrade to 2.3 and see if that helps. Is it recommended to follow the master branch?

I can also try and change the endpoint setting for arangodb to 0.0.0.0 and see if that makes a difference.

[jsteemann]

Thanks. I think in general the arangod server version should match the version of the PHP client used. It might work without that, but obviously an up-to-date driver might enable using more server features or better reflect changes in the server. At some points there are multiple stable ArangoDB versions out and in use, so we cannot predict if and when people will update their servers. So we cannot upgrade the master branch too early, and it might lag a bit behind the latest ArangoDB version. In case you want to be more up-to-date, there are the dedicated 2.x branches of the driver.

[realsurfer]

I upgraded to 2.4 and set the endpoint to 0.0.0.0 and still get the same error. What else can I test?

Thanks!

[realsurfer]

After changing the endpoint I am now getting connection refused when I am trying the curl request.

[jsteemann]

What is the exact endpoint setting you are using?

[realsurfer]

endpoint = tcp://0.0.0.0:8529

[jsteemann]

Ok, then it looks like the server cannot bind to this address. Is the server printing or logging any errors on start?

[realsurfer]

Doesn't look like it:

2015-01-29T14:13:49Z [4125] INFO using endpoint 'tcp://0.0.0.0:8529' for non-encrypted requests
2015-01-29T14:13:49Z [4125] INFO using default API compatibility: 20400
2015-01-29T14:13:49Z [4125] INFO JavaScript using startup '/usr/share/arangodb/js', application '/var/lib/arangodb-apps'
2015-01-29T14:13:52Z [4131] INFO ArangoDB 2.4.1 64bit -- ICU 52.1, V8 3.29.59, OpenSSL 1.0.1f 6 Jan 2014
2015-01-29T14:13:52Z [4131] INFO using default language 'en'
2015-01-29T14:13:52Z [4131] INFO starting up in supervisor mode```

[jsteemann]

The log entries starting at 14:13:52Z do not show a complete server start. Is the server actually running, i.e. is there an arangod process?

[realsurfer]

I did restart arango but now I did a server restart and the curl request works again. netstat -vatnshows that it is listening on 0.0.0.0 but I am getting the same error in PHP as before.

[jsteemann]

Can a simple standalone PHP program connect to the server?

<?php

$fp = fsockopen("127.0.0.1", 8529, $errno, $errmsg);

if (! $fp) {
  var_dump("cannot connect: ", $errno, $errmsg);
  exit(1);
}

fwrite($fp, "GET /_api/version HTTP/1.1\r\nHost: 127.0.0.1\r\n\r\n");
fflush($fp);

$buffer = fread($fp, 8192);
fclose($fp);

var_dump($buffer);

[realsurfer]

Yes that worked.

[jsteemann]

And this one, now using the driver (might need to adjust the path to the driver's autoloader):

<?php

namespace triagens\ArangoDb;

// get autoloader
require dirname(__FILE__) . DIRECTORY_SEPARATOR . 'lib' . DIRECTORY_SEPARATOR . 'triagens' . DIRECTORY_SEPARATOR . 'ArangoDb' . DIRECTORY_SEPARATOR . 'Autoloader.php';
Autoloader::init();

$enhancedTraceFunc = function ($data) {
  var_dump($data);
};

/* set up connection options */
$connectionOptions = array(
  ConnectionOptions::OPTION_ENDPOINT        => 'tcp://127.0.0.1:8529',
  ConnectionOptions::OPTION_CONNECTION      => 'Close',         
  ConnectionOptions::OPTION_AUTH_TYPE       => 'Basic',           
  /*
  ConnectionOptions::OPTION_AUTH_USER       => '',                 
  ConnectionOptions::OPTION_AUTH_PASSWD     => '',                  
  */
  ConnectionOptions::OPTION_TIMEOUT         => 30,                   
  ConnectionOptions::OPTION_TRACE           => $enhancedTraceFunc,
  ConnectionOptions::OPTION_ENHANCED_TRACE  => true
);

$connection = new Connection($connectionOptions);

var_dump($connection->get("/_api/version"));

[realsurfer]

That seems to also work. Strange! I haven't changed any of my code.

[realsurfer]

I'm setting the auth_user to root. Could that be it?

[jsteemann]

Can the test program still connect when you put in your regular connection options and authentication credentials? If not, then the issue is probably caused by configuration.

[realsurfer]

After some more testing it seems that some of my api calls work and some get a refused connection back for some reason. Could some collections have become corrupted in the upgrade process?

[jsteemann]

But I think then you shouldn't get a connection refused back. Which API calls exactly do return a connection refused? For example, /_api/version does not have anything to do with collections at all. And does the same API call reproducible return connection refused or just spuriously?

[realsurfer]

Sorry I meant my own api calls. Yes the same api call creates an exception in my code when I call it. Very strange as I haven't done anything except upgrade arangodb to the latest version. I now keep getting triagens\ArangoDb\ClientException: Got an invalid response from the server. How can I get more info about this exception?

[jsteemann]

The ClientException is a rather generic error. You can try turning on the trace functionality as in my last example. This will var_dump a lot of details, but it should print the HTTP transfer between your application and the server. Maybe there's something in it that reveals the actual problem.

[realsurfer]

I added the trace function with the laravel logging function Log::error(var_export($data, true)); but the only thing I am getting is 'send'which seems a little strange.

The exception is being thrown on line 285 in triagens/ArangoDb/HttpHelper.php

[jsteemann]

Then it seems like variable $parts contains something the driver does not expect. Can you provide the contents of this variable and also of $parsed, plus ideally the URL you are calling on the server?

[realsurfer]

Yes I will. I'm trying to figure out how I can log the data since I can't use the laravel logging function. When I var_dump the symfony exception handler takes over.

[jsteemann]

I think something simple like file_put_contents("/tmp/log", var_export($parts, true)); may do for a single dump.

[realsurfer]

Yes that will work! I logged parts then parsed and got:

array ( 0 => NULL, 1 => '', 2 => array ( ), )

[realsurfer]

parts was:

array (
  0 => '',
)

[jsteemann]

This explains the error. For which URL/action does that result come back? If you could provide this info that would be helpful. If it's not a build-in API URL, can you also provide $httpMessage?

[realsurfer]

I am only doing an ACL query statement in the php code reading some collections. The $httpMessage is empty with ''

[jsteemann]

Are you probably running into timeouts? Can you increase the timeout value and retry to rule this out?

Additionally, in Connection.php in method executeRequest, can you try dumping out $url, $request and the result of HttpHelper::transfer(), plus the time it spends in this call? Then we should be able to see the URL of the action plus the HTTP traffic if any, plus the function call duration (which might indicate there is timeout issue).

[realsurfer]

I will do that.

I have been testing my ACL code in the ACL editor and it only returns the message ERROR.

Here is the query I am running:

LET blockedUsers = (
                            FOR r IN NEIGHBORS(users, userRelationships, "1", "any", [{"type":"block"}])
                                RETURN r.vertex._key
                        )

                        LET blockedThreads = (
                            FOR p IN threadParticipants
                                FILTER p.userId IN (blockedUsers)
                                RETURN p.threadId
                        )

                        FOR t IN threads
                            FILTER t._key NOT IN (blockedThreads)
                            FOR p IN threadParticipants
                                FILTER t._key == p.threadId && p.userId == "1"
                                SORT t.dateUpdated DESC
                                RETURN MERGE( t, {
                                    "participants": (
                                        FOR ps IN threadParticipants
                                            FILTER t._key == ps.threadId
                                            return ps
                                    )
                                })

If I remove this line FILTER t._key NOT IN (blockedThreads)the query works.

[jsteemann]

I don't see any issue with the above query. Running it locally with empty collections (as I don't have any data to run this on) returns an empty result set as expected, so the query at least parses ok.

I just found ERROR will be printed in the AQL editor if the server response it gets after submitting the query is no JSON. But I have no idea why this could be. If the server does respond to the query, but with an empty response, this can be considered an error.

I'd like to reproduce this to find out the reason, but as I said, the query parses and executes ok in my local 2.4. So the query might only fail with specific datasets or indexes set up. Can you provide the execution plan for the query, i.e. the result of

curl --dump - -X POST "http://127.0.0.1:8529/_api/explain" --data '{"query":"LET blockedUsers = ( FOR r IN NEIGHBORS(users, userRelationships, \"1\", \"any\", [{\"type\":\"block\"}]) RETURN r.vertex._key) LET blockedThreads = ( FOR p IN threadParticipants FILTER p.userId IN (blockedUsers) RETURN p.threadId) FOR t IN threads FILTER t._key NOT IN (blockedThreads) FOR p IN threadParticipants FILTER t._key == p.threadId && p.userId == \"1\" SORT t.dateUpdated DESC RETURN MERGE( t, { \"participants\": ( FOR ps IN threadParticipants FILTER t._key == ps.threadId return ps) })"}'

[realsurfer]

It seems to have worked:

{"plan":{"nodes":[{"type":"SingletonNode","dependencies":[],"id":1,"estimatedCost":1,"estimatedNrItems":1},{"type":"SubqueryNode","dependencies":[1],"id":7,"estimatedCost":303,"estimatedNrItems":1,"subquery":{"nodes":[{"type":"SingletonNode","dependencies":[],"id":2,"estimatedCost":1,"estimatedNrItems":1},{"type":"CalculationNode","dependencies":[2],"id":3,"estimatedCost":2,"estimatedNrItems":1,"expression":{"type":"function call","name":"NEIGHBORS","subNodes":[{"type":"array","subNodes":[{"type":"collection","name":"users"},{"type":"collection","name":"userRelationships"},{"type":"value","value":"1"},{"type":"value","value":"any"},{"type":"array","subNodes":[{"type":"object","subNodes":[{"type":"object element","name":"type","subNodes":[{"type":"value","value":"block"}]}]}]}]}]},"outVariable":{"id":10,"name":"10"},"canThrow":true},{"type":"EnumerateListNode","dependencies":[3],"id":4,"estimatedCost":102,"estimatedNrItems":100,"inVariable":{"id":10,"name":"10"},"outVariable":{"id":0,"name":"r"}},{"type":"CalculationNode","dependencies":[4],"id":5,"estimatedCost":202,"estimatedNrItems":100,"expression":{"type":"attribute access","name":"_key","subNodes":[{"type":"attribute access","name":"vertex","subNodes":[{"type":"reference","name":"r","id":0}]}]},"outVariable":{"id":11,"name":"11"},"canThrow":false},{"type":"ReturnNode","dependencies":[5],"id":6,"estimatedCost":302,"estimatedNrItems":100,"inVariable":{"id":11,"name":"11"}}]},"outVariable":{"id":2,"name":"blockedUsers"}},{"type":"SubqueryNode","dependencies":[7],"id":14,"estimatedCost":304.41999979,"estimatedNrItems":1,"subquery":{"nodes":[{"type":"SingletonNode","dependencies":[],"id":8,"estimatedCost":1,"estimatedNrItems":1},{"type":"IndexRangeNode","dependencies":[8],"id":34,"estimatedCost":1.4199997899999999,"estimatedNrItems":0,"database":"wingle","collection":"threadParticipants","outVariable":{"id":3,"name":"p"},"ranges":[[{"variable":"p","attr":"userId","lowConst":{"include":false,"isConstant":true},"highConst":{"include":false,"isConstant":true},"lows":[{"bound":{"type":"reference","typeID":45,"name":"blockedUsers","id":2},"include":true,"isConstant":false}],"highs":[{"bound":{"type":"reference","typeID":45,"name":"blockedUsers","id":2},"include":true,"isConstant":false}],"valid":true,"equality":true}]],"index":{"type":"hash","id":"38100368878","unique":false,"fields":["userId"]},"reverse":false},{"type":"CalculationNode","dependencies":[34],"id":10,"estimatedCost":1.4199997899999999,"estimatedNrItems":0,"expression":{"type":"compare in","subNodes":[{"type":"attribute access","name":"userId","subNodes":[{"type":"reference","name":"p","id":3}]},{"type":"reference","name":"blockedUsers","id":2}]},"outVariable":{"id":12,"name":"12"},"canThrow":false},{"type":"FilterNode","dependencies":[10],"id":11,"estimatedCost":1.4199997899999999,"estimatedNrItems":0,"inVariable":{"id":12,"name":"12"}},{"type":"CalculationNode","dependencies":[11],"id":12,"estimatedCost":1.4199997899999999,"estimatedNrItems":0,"expression":{"type":"attribute access","name":"threadId","subNodes":[{"type":"reference","name":"p","id":3}]},"outVariable":{"id":13,"name":"13"},"canThrow":false},{"type":"ReturnNode","dependencies":[12],"id":13,"estimatedCost":1.4199997899999999,"estimatedNrItems":0,"inVariable":{"id":13,"name":"13"}}]},"outVariable":{"id":5,"name":"blockedThreads"}},{"type":"EnumerateCollectionNode","dependencies":[14],"id":15,"estimatedCost":325.41999979,"estimatedNrItems":21,"database":"wingle","collection":"threads","outVariable":{"id":6,"name":"t"},"random":false},{"type":"CalculationNode","dependencies":[15],"id":16,"estimatedCost":346.41999979,"estimatedNrItems":21,"expression":{"type":"compare not in","subNodes":[{"type":"attribute access","name":"_key","subNodes":[{"type":"reference","name":"t","id":6}]},{"type":"reference","name":"blockedThreads","id":5}]},"outVariable":{"id":14,"name":"14"},"canThrow":false},{"type":"FilterNode","dependencies":[16],"id":17,"estimatedCost":367.41999979,"estimatedNrItems":21,"inVariable":{"id":14,"name":"14"}},{"type":"CalculationNode","dependencies":[17],"id":21,"estimatedCost":388.41999979,"estimatedNrItems":21,"expression":{"type":"attribute access","name":"dateUpdated","subNodes":[{"type":"reference","name":"t","id":6}]},"outVariable":{"id":16,"name":"16"},"canThrow":false},{"type":"IndexRangeNode","dependencies":[21],"id":32,"estimatedCost":397.23999538000004,"estimatedNrItems":8,"database":"wingle","collection":"threadParticipants","outVariable":{"id":7,"name":"p"},"ranges":[[{"variable":"p","attr":"userId","lowConst":{"bound":"1","include":true,"isConstant":true},"highConst":{"bound":"1","include":true,"isConstant":true},"lows":[],"highs":[],"valid":true,"equality":true}]],"index":{"type":"hash","id":"38100368878","unique":false,"fields":["userId"]},"reverse":false},{"type":"CalculationNode","dependencies":[32],"id":19,"estimatedCost":405.23999538000004,"estimatedNrItems":8,"expression":{"type":"logical and","subNodes":[{"type":"compare ==","subNodes":[{"type":"attribute access","name":"_key","subNodes":[{"type":"reference","name":"t","id":6}]},{"type":"attribute access","name":"threadId","subNodes":[{"type":"reference","name":"p","id":7}]}]},{"type":"compare ==","subNodes":[{"type":"attribute access","name":"userId","subNodes":[{"type":"reference","name":"p","id":7}]},{"type":"value","value":"1"}]}]},"outVariable":{"id":15,"name":"15"},"canThrow":false},{"type":"FilterNode","dependencies":[19],"id":20,"estimatedCost":413.23999538000004,"estimatedNrItems":8,"inVariable":{"id":15,"name":"15"}},{"type":"SortNode","dependencies":[20],"id":22,"estimatedCost":429.8755277134387,"estimatedNrItems":8,"elements":[{"inVariable":{"id":16,"name":"16"},"ascending":false}],"stable":false},{"type":"SubqueryNode","dependencies":[22],"id":28,"estimatedCost":441.2355260334387,"estimatedNrItems":8,"subquery":{"nodes":[{"type":"SingletonNode","dependencies":[],"id":23,"estimatedCost":1,"estimatedNrItems":1},{"type":"IndexRangeNode","dependencies":[23],"id":35,"estimatedCost":1.4199997899999999,"estimatedNrItems":0,"database":"wingle","collection":"threadParticipants","outVariable":{"id":8,"name":"ps"},"ranges":[[{"variable":"ps","attr":"threadId","lowConst":{"include":false,"isConstant":true},"highConst":{"include":false,"isConstant":true},"lows":[{"bound":{"type":"attribute access","typeID":35,"name":"_key","subNodes":[{"type":"reference","typeID":45,"name":"t","id":6}]},"include":true,"isConstant":false}],"highs":[{"bound":{"type":"attribute access","typeID":35,"name":"_key","subNodes":[{"type":"reference","typeID":45,"name":"t","id":6}]},"include":true,"isConstant":false}],"valid":true,"equality":true}]],"index":{"type":"hash","id":"38100631022","unique":false,"fields":["threadId"]},"reverse":false},{"type":"CalculationNode","dependencies":[35],"id":25,"estimatedCost":1.4199997899999999,"estimatedNrItems":0,"expression":{"type":"compare ==","subNodes":[{"type":"attribute access","name":"_key","subNodes":[{"type":"reference","name":"t","id":6}]},{"type":"attribute access","name":"threadId","subNodes":[{"type":"reference","name":"ps","id":8}]}]},"outVariable":{"id":17,"name":"17"},"canThrow":false},{"type":"FilterNode","dependencies":[25],"id":26,"estimatedCost":1.4199997899999999,"estimatedNrItems":0,"inVariable":{"id":17,"name":"17"}},{"type":"ReturnNode","dependencies":[26],"id":27,"estimatedCost":1.4199997899999999,"estimatedNrItems":0,"inVariable":{"id":8,"name":"ps"}}]},"outVariable":{"id":9,"name":"9"}},{"type":"CalculationNode","dependencies":[28],"id":29,"estimatedCost":449.2355260334387,"estimatedNrItems":8,"expression":{"type":"function call","name":"MERGE","subNodes":[{"type":"array","subNodes":[{"type":"reference","name":"t","id":6},{"type":"object","subNodes":[{"type":"object element","name":"participants","subNodes":[{"type":"reference","name":"9","id":9}]}]}]}]},"outVariable":{"id":18,"name":"18"},"canThrow":false},{"type":"ReturnNode","dependencies":[29],"id":30,"estimatedCost":457.2355260334387,"estimatedNrItems":8,"inVariable":{"id":18,"name":"18"}}],"rules":["move-calculations-up","move-filters-up","move-calculations-up-2","move-filters-up-2","use-index-range"],"collections":[{"name":"threadParticipants","type":"read"},{"name":"threads","type":"read"},{"name":"userRelationships","type":"read"},{"name":"users","type":"read"}],"variables":[{"id":18,"name":"18"},{"id":17,"name":"17"},{"id":16,"name":"16"},{"id":15,"name":"15"},{"id":14,"name":"14"},{"id":13,"name":"13"},{"id":12,"name":"12"},{"id":11,"name":"11"},{"id":10,"name":"10"},{"id":0,"name":"r"},{"id":1,"name":"1"},{"id":2,"name":"blockedUsers"},{"id":3,"name":"p"},{"id":4,"name":"4"},{"id":5,"name":"blockedThreads"},{"id":6,"name":"t"},{"id":7,"name":"p"},{"id":8,"name":"ps"},{"id":9,"name":"9"}],"estimatedCost":457.2355260334387,"estimatedNrItems":8},"warnings":[],"stats":{"rulesExecuted":23,"rulesSkipped":0,"plansCreated":3},"error":false,"code":200}

[jsteemann]

Thanks, I think I got it now. The driver is ok, it is actually an issue in the server code that only happens if a certain set of indexes are present. It was fixed in 2.4 current already so I only saw it when I reverted from 2.4 current to tag 2.4.1. The fix will be included in the next 2.4 release (2.4.2) which we plan to start building tomorrow.

[realsurfer]

Great news! So hopefully I will just need to upgrade to 2.4.2 and these errors will disappear?

[realsurfer]

It would be great in the future if the php driver error messages would be a little more detailed to be able to quickly track down the problem. If it's an server error shouldn't it log to an error log somewhere?

[jsteemann]

Yes, the upgrade to 2.4.2 should fix this.

[jsteemann]

I have also added a simple mechanism for exception logging to the driver, as is described here: https://github.com/arangodb/arangodb-php/#logging_exceptions

By the way, our Github repositories have been renamed today from triAGENS/ArangoDB to arangodb/arangodb, and from triAGENS/ArangoDB-PHP to arangodb/arangodb-php. I hope that composer can handle this gracefully.

[realsurfer]

Thank you Jan! Really appreciate you taking your time to help out!

Will the new exception logging provide more info than before? Also, when you do think I will be able to upgrade to 2.4.2?

[jsteemann]

The exception logging will at least provide a stack trace and the error message. The error message in this case won't change, because the PHP client really cannot figure out sensibly what went wrong.

We plan to start building 2.4.2 today. Building for all platforms takes some time, but I guess it will be available on Monday the latest.

[realsurfer]

FYI, the upgrade to 2.4.2 solved this issue. Thanks once again Jan!

[jsteemann]

Thanks for confirming!