search

arangodb / arangodb-php

PHP ODM for ArangoDB
https://www.arangodb.com
Apache License 2.0
183 stars 44 forks source link

Error in HttpResponse.php #207

Closed realsurfer closed 7 years ago

realsurfer commented 7 years ago

Hello,

I just updated my lib to the latest 3.1 and I am getting PHP exceptions when I execute a statement. It's happening on different locations in my code but always the same exception. I haven't been able to replicate it and seems to happen randomly. Didn't encounter this with 3.0.

Exception message:

Undefined offset: 1 in /triagens/arangodb/lib/triagens/ArangoDb/HttpResponse.php:93

Thanks!

frankmayer commented 7 years ago

Hi @realsurfer , It has to do with http message parsing. Though, it has not shown up in the integration tests of the suite, which is strange.

Could you confirm/share some more details?

  1. If I understand you correctly, you are on tagged version 3.1.0 of the ArangoDB-PHP driver. (not devel)
  2. What ArangoDB version are you running (It should be the latest v3.1)?
  3. If there is any scenario where it happens more than in others, it might help to debug this.

Thanks

realsurfer commented 7 years ago

Thanks for your reply @frankmayer.

  1. Yes this is correct. Installed via composer.
  2. 3.1.11.
  3. I haven't yet seen a pattern. At first it happened executing the same statement but now it's happened in three different places with different AQL statements that have been stabile for a long time.

The errors are happening in my dev environment which is using PHP7. I haven't yet seen the error in my staging environment which is using PHP5.

frankmayer commented 7 years ago

Which exact Driver version is running on your production environment without the issues?

jsteemann commented 7 years ago

@frankmayer: I also got this message when running the driver tests in the devel branch today. I pushed a fix for this to the devel branch:

commit 3b58675671ba70868b34cf80181fab26eee002ad
Author: jsteemann <jan@arangodb.com>
Date:   Thu Feb 16 09:58:34 2017 +0100

    prevent PHP notices from occuring

I wasn't aware of that this happens in 3.1 as well. Not sure what the root cause of the issue is.

realsurfer commented 7 years ago

Both my dev and staging environments are using the same drivers and db. My production environment is still on ArangoDB 2.8 so not sure if that helps. I was previously using 3.0 on dev and staging.

@jsteemann Will suppressing the error result in valid data from the statement?

jsteemann commented 7 years ago

@realsurfer: the tests pass at least, so it looks like valid data is produced. I still have to look into this a bit deeper to find out what's causing the problem.

realsurfer commented 7 years ago

@jsteemann Great! Let me know if I can be of assistance. I am planning on pushing to production tomorrow so I guess I could manually apply your fix for now. What I find strange is that from my perspective the error seems random. Haven't been able to replicate it so far.

frankmayer commented 7 years ago

@jsteemann Thanks. From a quick look, the error indicates that no body (offset 1) could be produced from splitting the http reponse message, so I am not sure that silencing is a good solution.

I ran the test on the devel branch without your silencing patch in my own dev environment, against the latest docker 3.1.11 and strangely I am not getting any failures with this (I am getting failures with not getting the httpRequest data in the stats though, but that is a different matter)

frankmayer commented 7 years ago

@jsteemann ... and tests on TravisCI were not failing either.

jsteemann commented 7 years ago

I can reproduce the errors locally. I now went back to this commit 45616e4 and it works there again without errors. The really strange thing is that when I go back to HEAD and remove my silencing fix, it works too. Really mysterious...

frankmayer commented 7 years ago

Yes, it is...

I think, we should compare environments. For example I am running:

jsteemann commented 7 years ago

I am now pretty sure that the error is happening somewhat non-deterministically. I have now run the tests a few times, but always in the same environment and with the same driver & server code. Sometimes the problem occurs, sometimes it doesn't. I am currently looking into whether this is a driver or a server problem.

frankmayer commented 7 years ago

@jsteemann I could reproduce the issue when I ran the testsuite in parallel(starting one and after 1-2 seconds starting another one)! Of course the tests clashed between them, because of collection naming, but after I cancelled them out, and reran a single testsuite, I got all response related tests failing with the same exception. I noticed that the tests were taking a long time, so I check and the server was unresponsive. The dashboard was unresponsive too. After that I did a ^C on the console. ArangoDB replied with the normal Shutting down, but never did. I had to kill the complete container, which at the next docker run resulted in a successful "replaying WAL files..."

Maybe this helps you, finding the problem.

jsteemann commented 7 years ago

I think this was a server-side problem with the handling of requests that have the Connection: Close HTTP header set. In some cases it could happen that the connection was closed while the response was sent out to the client. As mentioned this only occured with Connection: Close and non-deterministically, which made it hard to reproduce. A fix for this is now in the 3.1 and devel branches of arangodb, and should become available with the next 3.1 release. As the issue only seemed to have occured with Connection: Close a fix is to use Connection: Keep-Alive from the client when setting up the connection from ArangoDB-PHP to ArangoDB.

realsurfer commented 7 years ago

Great that you figured it out! My connection is indeed set to "Close". Has this issue always been present or is it new for 3.1? In general would you recommend using Keep-Alive instead of Close?

frankmayer commented 7 years ago

ArangoDB's default is 'Keep-Alive', if not explicitly set by the client. see https://docs.arangodb.com/3.1/HTTP/General/#http-keep-alive.

Generally 'Keep-Alive' is better as it doesn't need to create new connections all the time, which is expensive. However, if you're using 'Keep-Alive', you have to be careful if you have a lot of parallel long running (or daemon) processes, they may use up all of the available connections.

frankmayer commented 7 years ago

I am afraid, there might still be issues, both with 'Close' and 'Keep-Alive'. I am not sure that it is 100% relevant to the issue, but I though to report them here.

I cloned the ArangoDB repo, chose branch 3.1 (32448ee) and compiled it.

Scenario 1 (with Connection : 'Close' )

The clashes which caused the server to hang in my report above, have now been revealed. I ran 3 testsuites of ArangoDB-PHP in parallel and they clashed, causing the server to fail. Here is what was logged from start to the failure...

2017-02-16T22:39:45Z [17090] INFO ArangoDB 3.1.11 [linux] 64bit, using VPack 0.1.30, ICU 54.1, V8 5.0.71.39, OpenSSL 1.0.2k  26 Jan 2017
2017-02-16T22:39:45Z [17090] INFO using SSL options: SSL_OP_CIPHER_SERVER_PREFERENCE, SSL_OP_TLS_ROLLBACK_BUG
2017-02-16T22:39:45Z [17090] INFO Starting up with role SINGLE
2017-02-16T22:39:45Z [17090] INFO Authentication is turned on
2017-02-16T22:39:45Z [17090] INFO Authentication system only
2017-02-16T22:39:45Z [17090] INFO Authentication for unix sockets is turned on
2017-02-16T22:39:45Z [17090] INFO file-descriptors (nofiles) hard limit is 65536, soft limit is 1024
2017-02-16T22:39:45Z [17090] INFO WAL directory '/opt/arangodb-git/database-dir/journals' does not exist. creating it...
2017-02-16T22:39:45Z [17090] INFO created base application directory '/opt/arangodb-git/arangodb/build/var/lib/arangodb3-apps/_db'
2017-02-16T22:39:45Z [17090] INFO JavaScript using startup '/opt/arangodb-git/arangodb/build/../js', application '/opt/arangodb-git/arangodb/build/var/lib/arangodb3-apps'
2017-02-16T22:39:47Z [17090] INFO using endpoint 'http+tcp://127.0.0.1:8529' for non-encrypted requests
2017-02-16T22:39:47Z [17090] INFO ArangoDB (version 3.1.11 [linux]) is ready for business. Have fun!
2017-02-16T22:40:04Z [17090] INFO created application directory '/opt/arangodb-git/arangodb/build/var/lib/arangodb3-apps/_db/ArangoTestSuiteDatabaseTest01' for database 'ArangoTestSuiteDatabaseTest01'
2017-02-16T22:40:44Z [17090] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-16T22:40:46Z [17090] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-16T22:40:49Z [17090] WARNING killing AQL query 235 'RETURN SLEEP(30)'
2017-02-16T22:40:59Z [17090] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.010282
2017-02-16T22:41:11Z [17090] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-16T22:41:11Z [17090] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-16T22:41:12Z [17090] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.001269
2017-02-16T22:43:27Z [17090] INFO created application directory '/opt/arangodb-git/arangodb/build/var/lib/arangodb3-apps/_db/ArangoTestSuiteDatabaseTest01' for database 'ArangoTestSuiteDatabaseTest01'
2017-02-16T22:43:28Z [17090] INFO created application directory '/opt/arangodb-git/arangodb/build/var/lib/arangodb3-apps/_db/ArangoTestSuiteDatabaseTest01' for database 'ArangoTestSuiteDatabaseTest01'
2017-02-16T22:44:06Z [17090] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-16T22:44:09Z [17090] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-16T22:44:12Z [17090] WARNING killing AQL query 715 'RETURN SLEEP(30)'
2017-02-16T22:44:22Z [17090] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.032882
2017-02-16T22:44:34Z [17090] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-16T22:44:34Z [17090] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-16T22:44:35Z [17090] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.006010
2017-02-16T22:45:59Z [17090] INFO created application directory '/opt/arangodb-git/arangodb/build/var/lib/arangodb3-apps/_db/ArangoTestSuiteDatabaseTest01' for database 'ArangoTestSuiteDatabaseTest01'
2017-02-16T22:45:59Z [17090] INFO created application directory '/opt/arangodb-git/arangodb/build/var/lib/arangodb3-apps/_db/ArangoTestSuiteDatabaseTest01' for database 'ArangoTestSuiteDatabaseTest01'
2017-02-16T22:46:14Z [17090] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-16T22:46:16Z [17090] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-16T22:46:19Z [17090] WARNING killing AQL query 1157 'RETURN SLEEP(30)'
2017-02-16T22:46:29Z [17090] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.002447
2017-02-16T22:46:42Z [17090] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-16T22:46:42Z [17090] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-16T22:46:42Z [17090] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.003399
2017-02-16T22:46:54Z [17090] INFO created application directory '/opt/arangodb-git/arangodb/build/var/lib/arangodb3-apps/_db/ArangoTestSuiteDatabaseTest01' for database 'ArangoTestSuiteDatabaseTest01'
2017-02-16T22:46:54Z [17090] INFO created application directory '/opt/arangodb-git/arangodb/build/var/lib/arangodb3-apps/_db/ArangoTestSuiteDatabaseTest01' for database 'ArangoTestSuiteDatabaseTest01'
2017-02-16T22:47:09Z [17090] INFO created application directory '/opt/arangodb-git/arangodb/build/var/lib/arangodb3-apps/_db/ArangoTestSuiteDatabaseTest01' for database 'ArangoTestSuiteDatabaseTest01'
2017-02-16T22:47:09Z [17090] INFO created application directory '/opt/arangodb-git/arangodb/build/var/lib/arangodb3-apps/_db/ArangoTestSuiteDatabaseTest01' for database 'ArangoTestSuiteDatabaseTest01'
2017-02-16T22:47:09Z [17090] ERROR JavaScript exception in file '/opt/arangodb-git/arangodb/js/common/modules/@arangodb/foxx/manager-utils.js' at 58,14: ArangoError 1228: database not found
2017-02-16T22:47:09Z [17090] ERROR !  var c = db._collection('_apps');
2017-02-16T22:47:09Z [17090] ERROR !             ^
2017-02-16T22:47:14Z [17090] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-16T22:47:14Z [17090] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-16T22:47:15Z [17090] ERROR Message: duplicate name: duplicate name
2017-02-16T22:47:15Z [17090] ERROR Service "/_api/gharial" encountered error 500 while handling POST http://localhost/_db/_system/_api/gharial/Graph1/vertex/ArangoDBPHPTestSuiteVertexTestCollection01
2017-02-16T22:47:15Z [17090] ERROR TypeError: g[collection].save is not a function
2017-02-16T22:47:15Z [17090] ERROR     at Route._handler (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:535:26)
2017-02-16T22:47:15Z [17090] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:412:15)
2017-02-16T22:47:15Z [17090] ERROR     at /opt/arangodb-git/arangodb/js/node/node_modules/lodash/lodash.js:10029:25
2017-02-16T22:47:15Z [17090] ERROR     at Middleware.router.use.e (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:72:5)
2017-02-16T22:47:15Z [17090] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:414:15)
2017-02-16T22:47:15Z [17090] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-16T22:47:15Z [17090] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-16T22:47:15Z [17090] ERROR     at dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:426:3)
2017-02-16T22:47:15Z [17090] ERROR     at Tree.dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:135:7)
2017-02-16T22:47:15Z [17090] ERROR     at callback (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/service.js:256:38)
2017-02-16T22:47:16Z [17090] ERROR Message: duplicate name: duplicate name
2017-02-16T22:47:16Z [17090] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-16T22:47:16Z [17090] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-16T22:47:18Z [17090] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-16T22:47:29Z [17090] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.002553
2017-02-16T22:47:29Z [17090] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.010490
2017-02-16T22:47:31Z [17090] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.003120
2017-02-16T22:47:42Z [17090] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-16T22:47:42Z [17090] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-16T22:47:42Z [17090] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.002554
2017-02-16T22:47:42Z [17090] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.006078
Segmentation fault (core dumped)

Scenario 2 (with Connection : 'Keep-Alive' )

If I run just one test-suite I get a failure in two tests, which were expecting a 412 response code and were getting a 408 response code instead: The tests are:

You should be able to reproduce those by setting 'Keep-Alive' in the bootsrap.php file.

Now, when I ran multiple test-suites, they clashed, but did not break the server. Did try it multiple times, with lots of parallel tests (10+) running without being able to reproduce the failing of the first scenario.

Lots of errors were spit out, but the server kept on running (no segmentation fault).

Both of these scenarios were run with ArangoDB-PHP devel (069cbe9)

To conclude:

Hope this helps further investigation.

frankmayer commented 7 years ago

@jsteemann I adapted the phpunit-tests to run once for 'Connection: Close' and once for 'Connection: Keep-Alive'. I created a separate branch for this, in order to merge it into devel later. The described failures in 'Scenario 2' can be reproduced and seen here: https://travis-ci.org/arangodb/arangodb-php/jobs/204454418

frankmayer commented 7 years ago

@realsurfer Did the Keep-Alive' setting fix the issue for you?

@jsteemann According to the latest tests (see above) the issue seems to still exist with Connection: 'Close' (and with nightly ArangoDB binaries being used in the tests). See aforementioned comments (https://github.com/arangodb/arangodb-php/issues/207#issuecomment-280497828 and https://github.com/arangodb/arangodb-php/issues/207#issuecomment-280513656). And as mentioned, there are two tests failing in Keep-Alive mode, which pass in Close mode. It looks like this might be a server issue.

jsteemann commented 7 years ago

@frankmayer: regarding the two failing test with Connection: Keep-Alive: I found an issue in the PHP driver with HTTP HEAD requests. arangod responds to HTTP HEAD requests with a response that has no body (which is intentional), but sets the Content-Length for the response to the length the body would have had. This is ok spec-wise, but some clients choke on that, because they wait for the actual body of the specified length to be returned by the server. curl is a notable example for a client that cannot handle this, and the PHP driver has had the same problem. I fixed that in the 3.1 and devel branches, and the two failing tests should now pass.

We have also tried to fix the segfault(s) uncovered by running the PHP driver's test in parallel. It turned out that it was not safe to have the same database being created and dropped by parallel threads. There was a race in the server that led to undefined behavior, and this was fixed today for 3.1 and devel. The same problem existed for renaming the same collection in parallel. That also should have been fixed in current 3.1 and devel.

I also tried to backport the fix to 3.1 that was necessary because of the changes in PHPUnit 6. Still the tests for 3.1 fail with some PHP versions and I currently don't know why.

Do the tests pass for you when running them locally with current 3.1/devel in parallel?

realsurfer commented 7 years ago

@frankmayer Yes it did thank you! I am now running 3.1 in production and so far I haven't had an exception.

frankmayer commented 7 years ago

@jsteemann I see. Thanks for the detailed explanation. :+1:

That were problems on multiple fronts then. I am glad, it was resolved.

Don't worry about the failing-test problems in the driver. I'l take care of those.

Closing this, as the underlying problems were fixed.

frankmayer commented 7 years ago

@jsteemann Oh, forgot to get back to you on your question. Yes, they pass locally in both scenarios.

frankmayer commented 7 years ago

@jsteemann just to follow up: a) While doing some more extensive parallel tests, ArangoDB hung itself again. Here's the log:

2017-02-24T00:15:34Z [23095] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487895315_018' for database 'ArangoTestSuiteDatabaseTest01_1487895315_018'
2017-02-24T00:15:34Z [23095] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487895313_4364' for database 'ArangoTestSuiteDatabaseTest01_1487895313_4364'
2017-02-24T00:15:35Z [23095] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487895311_9782' for database 'ArangoTestSuiteDatabaseTest01_1487895311_9782'
2017-02-24T00:15:35Z [23095] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487895312_4204' for database 'ArangoTestSuiteDatabaseTest01_1487895312_4204'
2017-02-24T00:15:36Z [23095] WARNING In database '_system': could not grant access to database user 'root': ArangoError 1200: conflict ArangoError: conflict\n    at Error (native)\n    at Object.exports.grantDatabase (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/users.js:472:9)\n    at /opt/arangodb-git/arangodb/js/server/upgrade-database.js:550:29\n    at Array.forEach (native)\n    at Object.addTask.task (/opt/arangodb-git/arangodb/js/server/upgrade-database.js:538:24)\n    at runTasks (/opt/arangodb-git/arangodb/js/server/upgrade-database.js:274:27)\n    at upgradeDatabase (/opt/arangodb-git/arangodb/js/server/upgrade-database.js:425:14)\n    at upgrade (/opt/arangodb-git/arangodb/js/server/upgrade-database.js:779:12)\n    at /opt/arangodb-git/arangodb/js/server/upgrade-database.js:786:10\n    at /opt/arangodb-git/arangodb/js/server/upgrade-database.js:787:2
2017-02-24T00:15:37Z [23095] ERROR encountered out-of-memory error
2017-02-24T00:15:37Z [23095] ERROR cannot create collection 'ArangoDB_PHP_TestSuite_TestCollection_01_1487895331_3264' in directory '/opt/arangodb-git/database-dir/databases/database-1': system error - -4292401747059184640 - 
2017-02-24T00:15:37Z [23095] ERROR encountered out-of-memory error
2017-02-24T00:15:37Z [23095] WARNING accept failed: Too many open files
2017-02-24T00:15:37Z [23095] ERROR {threads} scheduler loop caught an error, restarting
2017-02-24T00:15:37Z [23095] ERROR encountered out-of-memory error
2017-02-24T00:15:37Z [23095] ERROR encountered out-of-memory error
2017-02-24T00:15:37Z [23095] ERROR encountered out-of-memory error
2017-02-24T00:15:43Z [23095] ERROR cannot create json file '/opt/arangodb-git/database-dir/SHUTDOWN.tmp': Too many open files
2017-02-24T00:15:43Z [23095] ERROR unable to write WAL state file '/opt/arangodb-git/database-dir/SHUTDOWN'
2017-02-24T00:15:43Z [23095] ERROR encountered out-of-memory error
2017-02-24T00:15:44Z [23095] ERROR cannot create json file '/opt/arangodb-git/database-dir/SHUTDOWN.tmp': Too many open files
2017-02-24T00:15:44Z [23095] ERROR unable to write WAL state file '/opt/arangodb-git/database-dir/SHUTDOWN'
2017-02-24T00:15:44Z [23095] ERROR cannot create json file '/opt/arangodb-git/database-dir/SHUTDOWN.tmp': Too many open files
2017-02-24T00:15:44Z [23095] ERROR unable to write WAL state file '/opt/arangodb-git/database-dir/SHUTDOWN'
2017-02-24T00:15:44Z [23095] ERROR cannot create json file '/opt/arangodb-git/database-dir/SHUTDOWN.tmp': Too many open files
2017-02-24T00:15:44Z [23095] ERROR unable to write WAL state file '/opt/arangodb-git/database-dir/SHUTDOWN'
2017-02-24T00:15:44Z [23095] ERROR cannot create json file '/opt/arangodb-git/database-dir/SHUTDOWN.tmp': Too many open files
2017-02-24T00:15:44Z [23095] ERROR unable to write WAL state file '/opt/arangodb-git/database-dir/SHUTDOWN'
2017-02-24T00:15:44Z [23095] ERROR cannot create json file '/opt/arangodb-git/database-dir/databases/database-1613554/collection-1614624-3361596041/parameter.json.tmp': Too many open files
2017-02-24T00:15:44Z [23095] ERROR encountered out-of-memory error
^C2017-02-24T00:22:16Z [23095] INFO control-c received, beginning shut down sequence
2017-02-24T00:22:21Z [23095] INFO ArangoDB has been shut down

This was due to the soft limit of open files being too low (1024) After I reconfigured it, this did not happen again. However, there are some interesting messages to be found here. ;)

b) Now, with the open file limits adjusted, I ran some parallel tests again. So, here's anothe rlog file, wher e ArangoDB was not responding correctly after a few clashes. It didn't hang itself completely, but it there where wrong responses seen on the client. Again, there are some interesting messages to be found here. I think, again we have a few races (Gharial, Foxx?).

2017-02-24T01:34:51Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.009902
2017-02-24T01:35:37Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900132_2094' for database 'ArangoTestSuiteDatabaseTest01_1487900132_2094'
2017-02-24T01:35:37Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900132_2094' for database 'ArangoTestSuiteDatabaseTest01_1487900132_2094'
2017-02-24T01:35:38Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900133_535' for database 'ArangoTestSuiteDatabaseTest01_1487900133_535'
2017-02-24T01:35:39Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900134_5651' for database 'ArangoTestSuiteDatabaseTest01_1487900134_5651'
2017-02-24T01:35:40Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900135_1353' for database 'ArangoTestSuiteDatabaseTest01_1487900135_1353'
2017-02-24T01:35:41Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900135_6397' for database 'ArangoTestSuiteDatabaseTest01_1487900135_6397'
2017-02-24T01:35:41Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900136_1925' for database 'ArangoTestSuiteDatabaseTest01_1487900136_1925'
2017-02-24T01:35:42Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900136_1925' for database 'ArangoTestSuiteDatabaseTest01_1487900136_1925'
2017-02-24T01:35:43Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900136_7806' for database 'ArangoTestSuiteDatabaseTest01_1487900136_7806'
2017-02-24T01:35:45Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900137_3151' for database 'ArangoTestSuiteDatabaseTest01_1487900137_3151'
2017-02-24T01:35:45Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900137_787' for database 'ArangoTestSuiteDatabaseTest01_1487900137_787'
2017-02-24T01:35:46Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900138_1709' for database 'ArangoTestSuiteDatabaseTest01_1487900138_1709'
2017-02-24T01:35:47Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900138_6369' for database 'ArangoTestSuiteDatabaseTest01_1487900138_6369'
2017-02-24T01:36:12Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900156_7679' for database 'ArangoTestSuiteDatabaseTest01_1487900156_7679'
2017-02-24T01:36:13Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900156_7679' for database 'ArangoTestSuiteDatabaseTest01_1487900156_7679'
2017-02-24T01:36:20Z [9637] ERROR Cannot execute Foxx service at /hello_world: ArangoError: failed to invoke module
2017-02-24T01:36:20Z [9637] ERROR File: /opt/arangodb-git/arangodb/js/apps/_db/_system/hello_world/APP/lib/a.js
2017-02-24T01:36:20Z [9637] ERROR Cause: ArangoError: No such file or directory: system error
2017-02-24T01:36:20Z [9637] ERROR     at Error (native)
2017-02-24T01:36:20Z [9637] ERROR     at Object.global.DEFINE_MODULE.exports.readFileSync (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules/fs.js:451:25)
2017-02-24T01:36:20Z [9637] ERROR     at Object.Module._extensions..js (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:603:22)
2017-02-24T01:36:20Z [9637] ERROR     at Module.load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:539:36)
2017-02-24T01:36:20Z [9637] ERROR     at Function.Module._load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:484:16)
2017-02-24T01:36:20Z [9637] ERROR     at require (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:95:21)
2017-02-24T01:36:20Z [9637] ERROR     at Object.<anonymous> (/opt/arangodb-git/arangodb/js/apps/_db/_system/hello_world/APP/app.js:53:20)
2017-02-24T01:36:20Z [9637] ERROR     at Module._compile (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:586:8)
2017-02-24T01:36:20Z [9637] ERROR     at Object.Module._extensions..js (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:604:12)
2017-02-24T01:36:20Z [9637] ERROR     at Module.load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:539:36)
2017-02-24T01:36:20Z [9637] ERROR     at Module.load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:542:23)
2017-02-24T01:36:20Z [9637] ERROR     at Function.Module._load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:484:16)
2017-02-24T01:36:20Z [9637] ERROR     at require (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:95:21)
2017-02-24T01:36:20Z [9637] ERROR     at Object.<anonymous> (/opt/arangodb-git/arangodb/js/apps/_db/_system/hello_world/APP/app.js:53:20)
2017-02-24T01:36:20Z [9637] ERROR     at Module._compile (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:586:8)
2017-02-24T01:36:20Z [9637] ERROR     at Object.Module._extensions..js (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:604:12)
2017-02-24T01:36:20Z [9637] ERROR     at Module.load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:539:36)
2017-02-24T01:36:20Z [9637] ERROR     at Function.Module._load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:484:16)
2017-02-24T01:36:20Z [9637] ERROR     at require (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:95:21)
2017-02-24T01:36:20Z [9637] ERROR     at Object.<anonymous> (/opt/arangodb-git/arangodb/js/apps/_db/_system/hello_world/APP/index.js:32:25)
2017-02-24T01:36:20Z [9637] ERROR ArangoError: <path> must be a valid directory name (have '/opt/arangodb-git/arangodb/js/apps/_db/_system/hello_world/APP')
2017-02-24T01:36:20Z [9637] ERROR     at Error (native)
2017-02-24T01:36:20Z [9637] ERROR     at _install (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/manager.js:1131:10)
2017-02-24T01:36:20Z [9637] ERROR     at Object.install (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/manager.js:1174:17)
2017-02-24T01:36:20Z [9637] ERROR     at Object.actions.defineHttp.callback.easyPostCallback.callback [as callback] (/opt/arangodb-git/arangodb/js/actions/_admin/foxx/app.js:87:26)
2017-02-24T01:36:20Z [9637] ERROR     at Function.<anonymous> (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/actions.js:1910:25)
2017-02-24T01:36:20Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:36:20Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:36:20Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:36:20Z [9637] ERROR Cannot execute Foxx service at /hello_world: ArangoError: failed to invoke module
2017-02-24T01:36:20Z [9637] ERROR File: /opt/arangodb-git/arangodb/js/apps/_db/_system/hello_world/APP/app.js
2017-02-24T01:36:20Z [9637] ERROR Cause: ArangoError: cannot locate module
2017-02-24T01:36:20Z [9637] ERROR File: ./lib/a
2017-02-24T01:36:20Z [9637] ERROR     at Function.Module._resolveFilename (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:520:13)
2017-02-24T01:36:20Z [9637] ERROR     at Function.Module._load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:439:27)
2017-02-24T01:36:20Z [9637] ERROR     at require (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:95:21)
2017-02-24T01:36:20Z [9637] ERROR     at Object.<anonymous> (/opt/arangodb-git/arangodb/js/apps/_db/_system/hello_world/APP/app.js:53:20)
2017-02-24T01:36:20Z [9637] ERROR     at Module._compile (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:586:8)
2017-02-24T01:36:20Z [9637] ERROR     at Object.Module._extensions..js (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:604:12)
2017-02-24T01:36:20Z [9637] ERROR     at Module.load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:539:36)
2017-02-24T01:36:20Z [9637] ERROR     at Function.Module._load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:484:16)
2017-02-24T01:36:20Z [9637] ERROR     at require (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:95:21)
2017-02-24T01:36:20Z [9637] ERROR     at Object.<anonymous> (/opt/arangodb-git/arangodb/js/apps/_db/_system/hello_world/APP/index.js:32:25)
2017-02-24T01:36:20Z [9637] ERROR     at Module.load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:542:23)
2017-02-24T01:36:20Z [9637] ERROR     at Function.Module._load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:484:16)
2017-02-24T01:36:20Z [9637] ERROR     at require (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:95:21)
2017-02-24T01:36:20Z [9637] ERROR     at Object.<anonymous> (/opt/arangodb-git/arangodb/js/apps/_db/_system/hello_world/APP/index.js:32:25)
2017-02-24T01:36:20Z [9637] ERROR     at Module._compile (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:586:8)
2017-02-24T01:36:20Z [9637] ERROR     at Object.Module._extensions..js (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:604:12)
2017-02-24T01:36:20Z [9637] ERROR     at Module.load (/opt/arangodb-git/arangodb/build/../js/common/bootstrap/modules.js:539:36)
2017-02-24T01:36:20Z [9637] ERROR     at FoxxService.run (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/service.js:435:14)
2017-02-24T01:36:20Z [9637] ERROR     at exports.routeService (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/routing.js:153:40)
2017-02-24T01:36:20Z [9637] ERROR     at _install (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/manager.js:1127:7)
2017-02-24T01:36:20Z [9637] ERROR ArangoError: <path> must be a valid directory name (have '/opt/arangodb-git/arangodb/js/apps/_db/_system/hello_world/APP')
2017-02-24T01:36:20Z [9637] ERROR     at Error (native)
2017-02-24T01:36:20Z [9637] ERROR     at _install (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/manager.js:1131:10)
2017-02-24T01:36:20Z [9637] ERROR     at Object.install (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/manager.js:1174:17)
2017-02-24T01:36:20Z [9637] ERROR     at Object.actions.defineHttp.callback.easyPostCallback.callback [as callback] (/opt/arangodb-git/arangodb/js/actions/_admin/foxx/app.js:87:26)
2017-02-24T01:36:20Z [9637] ERROR     at Function.<anonymous> (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/actions.js:1910:25)
2017-02-24T01:36:20Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900163_6123' for database 'ArangoTestSuiteDatabaseTest01_1487900163_6123'
2017-02-24T01:36:24Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900164_122' for database 'ArangoTestSuiteDatabaseTest01_1487900164_122'
2017-02-24T01:36:27Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:36:27Z [9637] ERROR ArangoError: <path> must be a valid directory name (have '/opt/arangodb-git/arangodb/js/apps/_db/_system/hello_world/APP')
2017-02-24T01:36:27Z [9637] ERROR     at Error (native)
2017-02-24T01:36:27Z [9637] ERROR     at _install (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/manager.js:1131:10)
2017-02-24T01:36:27Z [9637] ERROR     at Object.install (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/manager.js:1174:17)
2017-02-24T01:36:27Z [9637] ERROR     at Object.actions.defineHttp.callback.easyPostCallback.callback [as callback] (/opt/arangodb-git/arangodb/js/actions/_admin/foxx/app.js:87:26)
2017-02-24T01:36:27Z [9637] ERROR     at Function.<anonymous> (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/actions.js:1910:25)
2017-02-24T01:36:27Z [9637] ERROR Message: duplicate name: duplicate name
2017-02-24T01:36:27Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:36:27Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:36:27Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:36:27Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:36:27Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:36:27Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:36:27Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:36:30Z [9637] WARNING killing AQL query 9400 'RETURN SLEEP(30)'
2017-02-24T01:36:30Z [9637] WARNING killing AQL query 9414 'RETURN SLEEP(30)'
2017-02-24T01:36:30Z [9637] WARNING killing AQL query 9431 'RETURN SLEEP(30)'
2017-02-24T01:36:30Z [9637] WARNING killing AQL query 9446 'RETURN SLEEP(30)'
2017-02-24T01:36:30Z [9637] WARNING killing AQL query 9454 'RETURN SLEEP(30)'
2017-02-24T01:36:30Z [9637] WARNING killing AQL query 9454 'RETURN SLEEP(30)'
2017-02-24T01:36:30Z [9637] WARNING killing AQL query 9456 'RETURN SLEEP(30)'
2017-02-24T01:36:30Z [9637] WARNING killing AQL query 9463 'RETURN SLEEP(30)'
2017-02-24T01:36:40Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.009673
2017-02-24T01:36:40Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.006588
2017-02-24T01:36:40Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.003678
2017-02-24T01:36:40Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.009176
2017-02-24T01:36:40Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.008009
2017-02-24T01:36:40Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.026884
2017-02-24T01:36:40Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.005511
2017-02-24T01:36:50Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 19.651218
2017-02-24T01:36:53Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.009401
2017-02-24T01:36:53Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.035731
2017-02-24T01:36:53Z [9637] WARNING got corrupted HTTP request '\x00ELETE'
2017-02-24T01:36:53Z [9637] WARNING got corrupted HTTP request '\x00ELETE'
2017-02-24T01:36:53Z [9637] WARNING got corrupted HTTP request '\x00ELETE'
2017-02-24T01:36:53Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.005013
2017-02-24T01:36:53Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.028112
2017-02-24T01:36:53Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.009225
2017-02-24T01:36:53Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:36:53Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.120380
2017-02-24T01:36:54Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900137_8202" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900137_8202.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:36:54Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900137_8202" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900137_8202.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:36:54Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900132_2382" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900132_2382.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:36:54Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900132_2382" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900132_2382.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:36:56Z [9637] WARNING killing AQL query 9476 'RETURN SLEEP(30)'
2017-02-24T01:36:56Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900133_5638" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900133_5638.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:01Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900133_5638" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900133_5638.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:01Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900137_3647" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900137_3647.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:01Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900137_3647" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900137_3647.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:03Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.015911
2017-02-24T01:37:03Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900134_5957" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900134_5957.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:06Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 16.057650
2017-02-24T01:37:06Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900134_5957" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900134_5957.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:08Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900138_6686" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900138_6686.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:08Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900138_6686" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900138_6686.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:08Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900136_8174" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900136_8174.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:08Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900136_8174" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900136_8174.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:11Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.007038
2017-02-24T01:37:14Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900135_7186" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900135_7186.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:14Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900135_7186" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900135_7186.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:15Z [9637] ERROR Service "/_api/gharial" encountered error 500 while handling POST http://localhost/_db/_system/_api/gharial/Graph1/vertex/ArangoDB_PHP_TestSuite_VertexTestCollection_01
2017-02-24T01:37:15Z [9637] ERROR TypeError: g[collection].save is not a function
2017-02-24T01:37:15Z [9637] ERROR     at Route._handler (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:535:26)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:412:15)
2017-02-24T01:37:15Z [9637] ERROR     at /opt/arangodb-git/arangodb/js/node/node_modules/lodash/lodash.js:10029:25
2017-02-24T01:37:15Z [9637] ERROR     at Middleware.router.use.e (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:72:5)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:414:15)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:37:15Z [9637] ERROR     at dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:426:3)
2017-02-24T01:37:15Z [9637] ERROR     at Tree.dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:135:7)
2017-02-24T01:37:15Z [9637] ERROR     at callback (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/service.js:256:38)
2017-02-24T01:37:15Z [9637] ERROR Service "/_api/gharial" encountered error 500 while handling GET http://localhost/_db/_system/_api/gharial/Graph1/vertex
2017-02-24T01:37:15Z [9637] ERROR TypeError: Cannot read property 'name' of undefined
2017-02-24T01:37:15Z [9637] ERROR     at req.pathParams.collectionObjects (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:337:15)
2017-02-24T01:37:15Z [9637] ERROR     at arrayMap (/opt/arangodb-git/arangodb/js/node/node_modules/lodash/lodash.js:653:23)
2017-02-24T01:37:15Z [9637] ERROR     at Function.map (/opt/arangodb-git/arangodb/js/node/node_modules/lodash/lodash.js:9533:14)
2017-02-24T01:37:15Z [9637] ERROR     at Route._handler (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:339:37)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:412:15)
2017-02-24T01:37:15Z [9637] ERROR     at /opt/arangodb-git/arangodb/js/node/node_modules/lodash/lodash.js:10029:25
2017-02-24T01:37:15Z [9637] ERROR     at Middleware.router.use.e (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:72:5)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:414:15)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:37:15Z [9637] ERROR Service "/_api/gharial" encountered error 500 while handling POST http://localhost/_db/_system/_api/gharial/Graph1/vertex/ArangoDB_PHP_TestSuite_VertexTestCollection_01
2017-02-24T01:37:15Z [9637] ERROR TypeError: g[collection].save is not a function
2017-02-24T01:37:15Z [9637] ERROR     at Route._handler (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:535:26)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:412:15)
2017-02-24T01:37:15Z [9637] ERROR     at /opt/arangodb-git/arangodb/js/node/node_modules/lodash/lodash.js:10029:25
2017-02-24T01:37:15Z [9637] ERROR     at Middleware.router.use.e (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:72:5)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:414:15)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:37:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:37:15Z [9637] ERROR     at dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:426:3)
2017-02-24T01:37:15Z [9637] ERROR     at Tree.dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:135:7)
2017-02-24T01:37:15Z [9637] ERROR     at callback (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/service.js:256:38)
2017-02-24T01:37:17Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:37:17Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:37:20Z [9637] WARNING killing AQL query 9543 'RETURN SLEEP(30)'
2017-02-24T01:37:20Z [9637] WARNING killing AQL query 10369 'RETURN SLEEP(30)'
2017-02-24T01:37:21Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900135_1647" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900135_1647.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:21Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900135_1647" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900135_1647.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:24Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.002733
2017-02-24T01:37:30Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.005229
2017-02-24T01:37:30Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.005278
2017-02-24T01:37:42Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900136_2241" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900136_2241.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:42Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900136_2241" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900136_2241.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:42Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900138_2117" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900138_2117.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:42Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900138_2117" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900138_2117.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:37:43Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.002359
2017-02-24T01:37:43Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.008483
2017-02-24T01:37:47Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(30)', took: 30.002945
2017-02-24T01:37:58Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:38:00Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:38:00Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:38:00Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:38:02Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:38:03Z [9637] WARNING killing AQL query 11258 'RETURN SLEEP(30)'
2017-02-24T01:38:03Z [9637] WARNING killing AQL query 11270 'RETURN SLEEP(30)'
2017-02-24T01:38:05Z [9637] WARNING killing AQL query 11353 'RETURN SLEEP(30)'
2017-02-24T01:38:13Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.008066
2017-02-24T01:38:13Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.007666
2017-02-24T01:38:15Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.000703
2017-02-24T01:38:25Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900163_6738" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900163_6738.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:38:25Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900163_6738" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900163_6738.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:38:25Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900157_4841" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900157_4841.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:38:25Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900157_4841" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900157_4841.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:38:26Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.007719
2017-02-24T01:38:26Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.002300
2017-02-24T01:38:27Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900164_3123" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900164_3123.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:38:27Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900164_3123" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900164_3123.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:38:28Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.006832
2017-02-24T01:38:33Z [9637] ERROR Service "/_api/gharial" encountered error 500 while handling POST http://localhost/_db/_system/_api/gharial/Graph1/vertex/ArangoDB_PHP_TestSuite_VertexTestCollection_01
2017-02-24T01:38:33Z [9637] ERROR TypeError: g[collection].save is not a function
2017-02-24T01:38:33Z [9637] ERROR     at Route._handler (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:535:26)
2017-02-24T01:38:33Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:412:15)
2017-02-24T01:38:33Z [9637] ERROR     at /opt/arangodb-git/arangodb/js/node/node_modules/lodash/lodash.js:10029:25
2017-02-24T01:38:33Z [9637] ERROR     at Middleware.router.use.e (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:72:5)
2017-02-24T01:38:33Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:414:15)
2017-02-24T01:38:33Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:38:33Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:38:33Z [9637] ERROR     at dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:426:3)
2017-02-24T01:38:33Z [9637] ERROR     at Tree.dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:135:7)
2017-02-24T01:38:33Z [9637] ERROR     at callback (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/service.js:256:38)
2017-02-24T01:42:06Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900513_8186' for database 'ArangoTestSuiteDatabaseTest01_1487900513_8186'
2017-02-24T01:42:06Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900513_8186' for database 'ArangoTestSuiteDatabaseTest01_1487900513_8186'
2017-02-24T01:42:07Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900513_8186' for database 'ArangoTestSuiteDatabaseTest01_1487900513_8186'
2017-02-24T01:42:25Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:47:40Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:47:43Z [9637] WARNING killing AQL query 12069 'RETURN SLEEP(30)'
2017-02-24T01:47:53Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.002494
2017-02-24T01:48:05Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900513_9417" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900513_9417.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:48:05Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900513_9417" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900513_9417.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:48:06Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.002889
2017-02-24T01:49:21Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900956_2409' for database 'ArangoTestSuiteDatabaseTest01_1487900956_2409'
2017-02-24T01:49:21Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900956_2409' for database 'ArangoTestSuiteDatabaseTest01_1487900956_2409'
2017-02-24T01:49:23Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900958_5512' for database 'ArangoTestSuiteDatabaseTest01_1487900958_5512'
2017-02-24T01:49:25Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900960_0683' for database 'ArangoTestSuiteDatabaseTest01_1487900960_0683'
2017-02-24T01:49:26Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900961_4265' for database 'ArangoTestSuiteDatabaseTest01_1487900961_4265'
2017-02-24T01:49:26Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900961_865' for database 'ArangoTestSuiteDatabaseTest01_1487900961_865'
2017-02-24T01:49:27Z [9637] WARNING In database '_system': could not grant access to database user 'root': ArangoError 1200: conflict ArangoError: conflict\n    at Error (native)\n    at Object.exports.grantDatabase (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/users.js:472:9)\n    at /opt/arangodb-git/arangodb/js/server/upgrade-database.js:550:29\n    at Array.forEach (native)\n    at Object.addTask.task (/opt/arangodb-git/arangodb/js/server/upgrade-database.js:538:24)\n    at runTasks (/opt/arangodb-git/arangodb/js/server/upgrade-database.js:274:27)\n    at upgradeDatabase (/opt/arangodb-git/arangodb/js/server/upgrade-database.js:425:14)\n    at upgrade (/opt/arangodb-git/arangodb/js/server/upgrade-database.js:779:12)\n    at /opt/arangodb-git/arangodb/js/server/upgrade-database.js:786:10\n    at /opt/arangodb-git/arangodb/js/server/upgrade-database.js:787:2
2017-02-24T01:49:29Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900963_909' for database 'ArangoTestSuiteDatabaseTest01_1487900963_909'
2017-02-24T01:49:30Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900964_6713' for database 'ArangoTestSuiteDatabaseTest01_1487900964_6713'
2017-02-24T01:49:30Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900964_9121' for database 'ArangoTestSuiteDatabaseTest01_1487900964_9121'
2017-02-24T01:49:37Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900969_1325' for database 'ArangoTestSuiteDatabaseTest01_1487900969_1325'
2017-02-24T01:49:38Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900970_2292' for database 'ArangoTestSuiteDatabaseTest01_1487900970_2292'
2017-02-24T01:49:38Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900971_658' for database 'ArangoTestSuiteDatabaseTest01_1487900971_658'
2017-02-24T01:49:46Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900972_4429' for database 'ArangoTestSuiteDatabaseTest01_1487900972_4429'
2017-02-24T01:49:46Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900972_4429' for database 'ArangoTestSuiteDatabaseTest01_1487900972_4429'
2017-02-24T01:49:47Z [9637] INFO created application directory '/opt/arangodb-git/arangodb/build/../js/apps/_db/ArangoTestSuiteDatabaseTest01_1487900972_4429' for database 'ArangoTestSuiteDatabaseTest01_1487900972_4429'
2017-02-24T01:50:00Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:50:01Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:50:06Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:50:06Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:50:07Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:50:07Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:50:08Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:50:11Z [9637] INFO collection 'hello_world_texts' already exists. Leaving it untouched.
2017-02-24T01:50:13Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:50:13Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:50:13Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:50:14Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:50:14Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:50:14Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:50:14Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:50:14Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:50:16Z [9637] WARNING killing AQL query 14581 'RETURN SLEEP(30)'
2017-02-24T01:50:16Z [9637] WARNING killing AQL query 14604 'RETURN SLEEP(30)'
2017-02-24T01:50:16Z [9637] WARNING killing AQL query 14805 'RETURN SLEEP(30)'
2017-02-24T01:50:17Z [9637] WARNING killing AQL query 14617 'RETURN SLEEP(30)'
2017-02-24T01:50:17Z [9637] WARNING killing AQL query 14691 'RETURN SLEEP(30)'
2017-02-24T01:50:17Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:50:17Z [9637] WARNING killing AQL query 14776 'RETURN SLEEP(30)'
2017-02-24T01:50:17Z [9637] WARNING killing AQL query 14776 'RETURN SLEEP(30)'
2017-02-24T01:50:17Z [9637] WARNING killing AQL query 14793 'RETURN SLEEP(30)'
2017-02-24T01:50:20Z [9637] WARNING killing AQL query 14794 'RETURN SLEEP(30)'
2017-02-24T01:50:20Z [9637] WARNING killing AQL query 14823 'RETURN SLEEP(30)'
2017-02-24T01:50:20Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:50:26Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.006471
2017-02-24T01:50:26Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.012210
2017-02-24T01:50:26Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.008858
2017-02-24T01:50:27Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.018906
2017-02-24T01:50:27Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.055056
2017-02-24T01:50:27Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.054289
2017-02-24T01:50:30Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 12.694461
2017-02-24T01:50:36Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 18.938464
2017-02-24T01:50:36Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 16.060899
2017-02-24T01:50:36Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 16.154223
2017-02-24T01:50:40Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.489062
2017-02-24T01:50:40Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.792977
2017-02-24T01:50:40Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.375631
2017-02-24T01:50:43Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 15.696346
2017-02-24T01:50:43Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:50:46Z [9637] WARNING killing AQL query 14829 'RETURN SLEEP(30)'
2017-02-24T01:50:49Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 19.301230
2017-02-24T01:50:49Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 19.437243
2017-02-24T01:50:49Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.102587
2017-02-24T01:50:50Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900958_5795" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900958_5795.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:50:50Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900958_5795" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900958_5795.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:50:50Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900964_949" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900964_949.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:50:53Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 16.733599
2017-02-24T01:50:53Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900964_949" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900964_949.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:50:53Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 17.018172
2017-02-24T01:50:53Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900964_8092" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900964_8092.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:50:53Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 16.864832
2017-02-24T01:50:53Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900964_8092" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900964_8092.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:50:56Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.010634
2017-02-24T01:50:56Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900956_2733" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900956_2733.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:50:57Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900956_2733" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900956_2733.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:00Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900961_9008" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900961_9008.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:00Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900961_9008" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900961_9008.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:00Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900970_2643" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900970_2643.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:00Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900970_2643" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900970_2643.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:04Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900969_163" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900969_163.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:04Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900969_163" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900969_163.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:07Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900963_9975" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900963_9975.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:07Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900963_9975" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900963_9975.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:07Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900961_4583" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900961_4583.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:07Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900960_0972" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900960_0972.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:10Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.009728
2017-02-24T01:51:10Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900961_4583" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900961_4583.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:11Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900960_0972" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900960_0972.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:12Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900971_7326" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900971_7326.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:13Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(30)', took: 30.001592
2017-02-24T01:51:13Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900971_7326" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900971_7326.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:15Z [9637] ERROR Service "/_api/gharial" encountered error 500 while handling GET http://localhost/_db/_system/_api/gharial/Graph1/vertex/ArangoDB_PHP_TestSuite_VertexTestCollection_01/vertex_eve
2017-02-24T01:51:15Z [9637] ERROR TypeError: g[collection].document is not a function
2017-02-24T01:51:15Z [9637] ERROR     at Route._handler (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:565:25)
2017-02-24T01:51:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:412:15)
2017-02-24T01:51:15Z [9637] ERROR     at /opt/arangodb-git/arangodb/js/node/node_modules/lodash/lodash.js:10029:25
2017-02-24T01:51:15Z [9637] ERROR     at Middleware.router.use.e (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:72:5)
2017-02-24T01:51:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:414:15)
2017-02-24T01:51:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:51:15Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:51:15Z [9637] ERROR     at dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:426:3)
2017-02-24T01:51:15Z [9637] ERROR     at Tree.dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:135:7)
2017-02-24T01:51:15Z [9637] ERROR     at callback (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/service.js:256:38)
2017-02-24T01:51:15Z [9637] WARNING about to execute: 'require("internal").db._query("RETURN SLEEP(30)");'
2017-02-24T01:51:18Z [9637] ERROR Service "/_api/gharial" encountered error 500 while handling POST http://localhost/_db/_system/_api/gharial/Graph1/vertex/ArangoDB_PHP_TestSuite_VertexTestCollection_01
2017-02-24T01:51:18Z [9637] ERROR TypeError: g[collection].save is not a function
2017-02-24T01:51:18Z [9637] ERROR     at Route._handler (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:535:26)
2017-02-24T01:51:18Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:412:15)
2017-02-24T01:51:18Z [9637] ERROR     at /opt/arangodb-git/arangodb/js/node/node_modules/lodash/lodash.js:10029:25
2017-02-24T01:51:18Z [9637] ERROR     at Middleware.router.use.e (/opt/arangodb-git/arangodb/js/apps/system/_api/gharial/APP/gharial.js:72:5)
2017-02-24T01:51:18Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:414:15)
2017-02-24T01:51:18Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:51:18Z [9637] ERROR     at next (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:410:7)
2017-02-24T01:51:18Z [9637] ERROR     at dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:426:3)
2017-02-24T01:51:18Z [9637] ERROR     at Tree.dispatch (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/router/tree.js:135:7)
2017-02-24T01:51:18Z [9637] ERROR     at callback (/opt/arangodb-git/arangodb/js/server/modules/@arangodb/foxx/service.js:256:38)
2017-02-24T01:51:18Z [9637] WARNING killing AQL query 15437 'RETURN SLEEP(30)'
2017-02-24T01:51:28Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(10)', took: 10.009988
2017-02-24T01:51:40Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_02_1487900972_5628" ] }, action: function () {\n          require("internal").wait(7, false);\n          var db = require("internal").db;\n          db.ArangoDB_PHP_TestSuite_TestCollection_01_1487900972_5628.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:40Z [9637] WARNING about to execute: '\n        try {\n          require("internal").db._executeTransaction({ collections: { write: [ "ArangoDB_PHP_TestSuite_TestCollection_01_1487900972_5628" ] }, action: function () {\n            require("internal").wait(7, false);\n            var db = require("internal").db;\n            db.ArangoDB_PHP_TestSuite_TestCollection_02_1487900972_5628.any();\n          }});\n          return { message: "ok" };\n        } catch (err) {\n          return { message: err.errorNum };\n        }\n        '
2017-02-24T01:51:41Z [9637] WARNING {queries} slow query: 'RETURN SLEEP(13)', took: 13.002320

c) The same tests that currently fail on Travis with ArangoDB-PHP 3.1 and ArangoDB 3.1 branch, are running without issues locally with a fresh compiled ArangoDB. After having restarted some of them, it turns out that the failure is happening randomly.

It seems like somehow Travis denies requests after a while, in those cases. Maybe some combination of libs that trigger that strange behavior on Travis? Maybe to many file handles are open?

Though, I noticed, that if the Driver 3.1 is run against a the devel-nightly of ArangoDB, this doesn't happen. (It failed for another reason (some httpRequests attribute missing), which I think is some behavior that has changed from ArangoDB 3.1 to 3.2)

jsteemann commented 7 years ago

@frankmayer:

a) when the number of available file descriptors is too low, ArangoDB may fail at various places whenever it needs to access a file. This is not ideal but currently unavoidable. The issue can easily be "configured away" by adjusting the number of available open file descriptors for the arangod process.

b) I think if the PHP driver tests are run in parallel, ArangoDB is allowed to fail while processing some of the requests. With "fail" I mean it should not crash or lock itself up, but it is allowed to fail while processing some multi-step operations. For example, it can fail anywhere when doing things with a database that a parallel client request is deleting at the very same time. The error messages I see in the b) logs seem to be causes by such cases.

c) do you mean that when running the 3.1 tests against ArangoDB 3.1 locally, you can reproduce the issues that TravisCI has? I tried running the 3.1 tests against a local ArangoDB 3.1 in a loop, and no problems occurred. I wasn't able to reproduce the problem TravisCI had with 3.1. Do you have any suggestion for me how to reproduce this locally? Thanks!

frankmayer commented 7 years ago

@jsteemann

a) Yes, I know it's unavoidable. Just an idea, maybe there could be some elegant solution to "prevent" the "final blow", by somehow "throttling" the needed file descriptor usage, when it's close to the limit or let the client know, that they are operating on the edge? Just had a thought of this now, maybe the clients could also poll for file descriptor usage through the API, every now and then, and adjust (Either through a dedicated call or as part of the statistics)? Or even, if the server itself, sees that it's getting near any limit (descriptors, memory, disk?), it could flag that somehow in the response(s), where the clients could look out for that, and adjust (throttle requests, fire off alarms, etc...)?

b) I totally agree, that in multi-step operations there might be some failures if those tests are run in parallel. But, what I saw, was that some (unrelated) tests were getting unexpected responses from the server for a while, just after those warnings/errors were issued, like if something was "hanging"/recovering. I will try to reproduce it and give you more detailed information on that.

c) No, I meant that I cannot reproduce the TravisCi issue locally and therefore I think that there is some problem in the TravisCI test environment setup (related specifically to the 3.1 branch), not in the driver.