search

mongodb / mongo-php-library

The Official MongoDB PHP library
https://mongodb.com/docs/php-library/current/
Apache License 2.0
1.6k stars 262 forks source link

Connection timeout parameter being ignored? #145

Closed zachrattner closed 7 years ago

zachrattner commented 8 years ago

I've recently upgraded from the old MongoClient API to the latest version. It seems the new API ignores connection timeout requests.

To test, I've intentionally added an incorrect hostname and set these three values to 1000 ms:

Sample code:

$start = microtime(true);

// Initialize connection string with timeouts
$manager = new MongoDB\Driver\Manager('mongodb://user:pass@host:port/db?socketTimeoutMS=1000&wTimeoutMS=1000&connectTimeoutMS=1000');
echo 'Created manager: ' . number_format(microtime(true) - $start, 6) . "\n";

// Attempt to insert something since the manager connection is lazy
$bulk      = new MongoDB\Driver\BulkWrite();
$toInsert  = $bulk->insert(['hi' => 'there']);

try
{
    echo 'Created bulk write: ' . number_format(microtime(true) - $start, 6) . "\n";
    $rsp = $manager->executeBulkWrite('mydatabase.MyCollection', $bulk);

    // We'll get here if no exception is thrown
    echo 'Finished bulk write successfully: ' . number_format(microtime(true) - $start, 6);
}
catch (Exception $e)
{
    // Print time it took to get here and the exception type/message
    echo 'Exception thrown from executeBulkWrite: ' . number_format(microtime(true) - $start, 6) . "\n";
    echo get_class($e) . ':' . $e->getMessage();
}

Output:

Created manager: 0.000043
Created bulk write: 0.000058
Exception thrown from executeBulkWrite: 10.027685
MongoDB\\Driver\\Exception\\ConnectionTimeoutException:No suitable servers found (`serverselectiontryonce` set): [Failed connecting to 'example.com:00000': php_network_getaddresses: getaddrinfo failed: Name or service not known]

Why does the timeout always take 10 seconds to complete, regardless of what I put for the the timeout commands?

FWIW, I've also tried this format:

$opts = ['socketTimeoutMS' => 1000, 'wTimeoutMS' => 1000, 'connectTimeoutMS' => 1000];
$manager = new MongoDB\Driver\Manager('mongodb://user:pass@host:port/db', $opts);
pinkladywithcoco commented 8 years ago

Hi,

I agree that is a big problem. On the old client, you can set a like that timeout:

 try {

    $mongo = new MongoClient("mongodb:/domainsharded.com:27017,domainsharded2.com:27017",

                             array("connectTimeoutMS" => 1000)

                             );

} catch (MongoConnectionException $e) {

        echo "Connection fail";
}

It will try to connect to the first mongos instance if that connection is not made during 1 second it will try to connect the second one. If both cant then it will say: Connection fail.

On the new API if we do the same:

 try {

    $mongo = new MongoDB\Driver\Manager("mongodb:/domainsharded.com:27017,domainsharded2.com:27017",

                             array("connectTimeoutMS" => 1000)

                             );

} catch (Exception $e) {

        echo "Connection fail";
}

It will not timeout during 1 second. It will also not try second mongos instance if the first one fails. this is a serious issue and makes the new api useless to use if not fixed.

jmikola commented 8 years ago

@zachrattner: After some investigation, I believe this is a bug with the "connectTimeoutMS" parsing being case-sensitive (for array options) in the PHP extension. All other options use case-insensitive parsing. I've opened PHPC-655 to track it. Just to note: the HHVM driver does not have the same bug, as it does not construct its own streams.

For an immediate fix, you should be able to use "connecttimeoutms" key in your options array. Alternatively, you can switch to including this as a query string parameter in your connection URI (that parsing is case-insensitive).

zachrattner commented 8 years ago

Thanks for the analysis @jmikola. As you can see in the sample code, I did add connectTimeoutMS as a URI parameter and still saw the same issue. Furthermore, when I moved to using the options array, making the key lowercase didn't seem to change anything.

This code snippet still takes 10 seconds to time out:

$opts = ['sockettimeoutms' => 1000, 'wtimeoutms' => 1000, 'connecttimeoutms' => 1000];
$manager = new MongoDB\Driver\Manager('mongodb://user:pass@host:port/db', $opts);

I'm using PHP 7.0.4 in case you need the info.

zachrattner commented 8 years ago

@pinkladywithcoco Curious to hear if using URL parameters or lowercase keys works for you. What version of PHP are you using?

jmikola commented 8 years ago

@zachrattner: Can you add the following around the try/catch that initializes the socket and share the output?

ini_set('mongodb.debug', 'stderr');

// try/catch

ini_set('mongodb.debug', 'off');

Alternatively, you can enable mongodb.debug for the entirety of the script and share that.

pinkladywithcoco commented 8 years ago

Hi,

zachrattner commented 8 years ago

@pinkladywithcoco seems we have the same issue. Glad I'm not the only one :smiley:

@jmikola I set mongodb.debug=stderr in php.ini and restarted PHP FPM. To verify the change, I added this to the start of the script: var_dump(ini_get('mongodb.debug'));

Output is: string(6) "stderr"

Exception I get is:

MongoDB\Driver\Exception\ConnectionTimeoutException:No suitable servers found (serverselectiontryonce set): [Failed connecting to 'something.example.com:25239': php_network_getaddresses: getaddrinfo failed: Name or service not known]

I don't seem to get any additional info as a result of making the php.ini modification.

It's worth noting that this error happens for a DNS name that doesn't exist (something.example.com) and the timeout is ignored.

For a valid domain name with the requested port closed (zachrattner.com), this is the error (timeout is also ignored):

2016/03/28 19:42:57 [error] 7657#7657: *543 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 192.168.xxx.xxx, server: localhost, request: "POST /path/to/url HTTP/1.1", upstream: "fastcgi://unix:/var/run/php7-fpm.sock", host: "localhost"

If I use a valid hostname with incorrect credentials, I do get an AuthenticationException within the expected period of time.

jmikola commented 8 years ago

@zachrattner: I didn't realize you were using FPM. "stderr" logging will work fine for a CLI script, so if this is reproducible in the CLI I'd suggest doing so. If you'd like to stick with FPM, you can set mongodb.debug to a directory and the driver should create output logs for each request in there (as mentioned here).

Given that the exception messages vary for an invalid host (i.e. DNS resolution fails) and a valid host with a closed port, does each scenario result in the same 10-second delay?

zachrattner commented 8 years ago

@jmikola sorry for the delay -- been on travel past few days. I was able to collect the logs you requested. See below. FYI, I'm running PHP 7.0.5 now and seeing the same issue with 30 seconds now instead of 10.

A valid host with a closed port throws a ConnectionTimeoutException almost immediately (as expected) with the message Connection refused..

Invalid Host

>> time php test.php
[2016-04-01T16:15:35+00:00]     PHONGO: DEBUG   > Connection string: 'mongodb://user:password@something.example.com:27017/db'
[2016-04-01T16:15:35+00:00]     PHONGO: TRACE   > ENTRY: php_phongo_make_mongo_client():1944
[2016-04-01T16:15:35+00:00]     PHONGO: DEBUG   > Creating Manager, phongo-1.1.5[stable] - mongoc-1.3.3(bundled), libbson-1.3.3(bundled), php-7.0.5
[2016-04-01T16:15:35+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_init():51
[2016-04-01T16:15:35+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_init():68
[2016-04-01T16:15:35+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_init():87
[2016-04-01T16:15:35+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_init():123
[2016-04-01T16:15:35+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_init():1570
[2016-04-01T16:15:35+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_init():1593
[2016-04-01T16:15:35+00:00]     client: DEBUG   > Using custom stream initiator.
[2016-04-01T16:15:35+00:00]     PHONGO: TRACE   >  EXIT: php_phongo_make_mongo_client():2042
[2016-04-01T16:15:35+00:00] collection: TRACE   > ENTRY: _mongoc_collection_new():170
[2016-04-01T16:15:35+00:00] collection: TRACE   >  EXIT: _mongoc_collection_new():199
[2016-04-01T16:15:35+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_new():85
[2016-04-01T16:15:35+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_new():235
[2016-04-01T16:15:35+00:00] collection: TRACE   > ENTRY: mongoc_collection_destroy():223
[2016-04-01T16:15:35+00:00] collection: TRACE   >  EXIT: mongoc_collection_destroy():248
[2016-04-01T16:15:35+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_next():964
[2016-04-01T16:15:35+00:00]     cursor: TRACE   > TRACE: mongoc_cursor_next():969 cursor_id(0)
[2016-04-01T16:15:35+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_next():1025
[2016-04-01T16:15:35+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_initial_query():346
[2016-04-01T16:15:35+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_fetch_stream():305
[2016-04-01T16:15:35+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_stream_for_optype():1658
[2016-04-01T16:15:35+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1170
[2016-04-01T16:15:35+00:00]     PHONGO: DEBUG   > Connecting to 'something.example.com:27017[mongodb://user:password@something.example.com:27017/db]'
[2016-04-01T16:15:50+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1220
[2016-04-01T16:15:50+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():383
[2016-04-01T16:15:50+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():389
[2016-04-01T16:15:50+00:00]     mongoc: TRACE   > TRACE: mongoc_topology_description_handle_ismaster():1400 No transition entry to 4 for 0
[2016-04-01T16:15:50+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_select():493
[2016-04-01T16:15:50+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_select():507
[2016-04-01T16:15:50+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_stream_for_optype():1670
[2016-04-01T16:15:50+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_fetch_stream():322
[2016-04-01T16:15:50+00:00]     cursor: TRACE   >  GOTO: _mongoc_cursor_initial_query():353 done
[2016-04-01T16:15:50+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_initial_query():382
[2016-04-01T16:15:50+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_next():1079
[2016-04-01T16:15:50+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_next():1000
[2016-04-01T16:15:50+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_error():923
[2016-04-01T16:15:50+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_error():941
[2016-04-01T16:15:50+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_error():951
[2016-04-01T16:15:50+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_error():933
[2016-04-01T16:15:50+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_destroy():242
[2016-04-01T16:15:50+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_destroy():259
[2016-04-01T16:15:50+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_destroy():296
[2016-04-01T16:15:50+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_destroy():252
[2016-04-01T16:15:50+00:00] collection: TRACE   > ENTRY: _mongoc_collection_new():170
[2016-04-01T16:15:50+00:00] collection: TRACE   >  EXIT: _mongoc_collection_new():199
[2016-04-01T16:15:50+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_new():85
[2016-04-01T16:15:50+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_new():235
[2016-04-01T16:15:50+00:00] collection: TRACE   > ENTRY: mongoc_collection_destroy():223
[2016-04-01T16:15:50+00:00] collection: TRACE   >  EXIT: mongoc_collection_destroy():248
[2016-04-01T16:15:50+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_next():964
[2016-04-01T16:15:50+00:00]     cursor: TRACE   > TRACE: mongoc_cursor_next():969 cursor_id(0)
[2016-04-01T16:15:50+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_next():1025
[2016-04-01T16:15:50+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_initial_query():346
[2016-04-01T16:15:50+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_fetch_stream():305
[2016-04-01T16:15:50+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_stream_for_optype():1658
[2016-04-01T16:15:50+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1170
[2016-04-01T16:15:50+00:00]     PHONGO: DEBUG   > Connecting to 'something.example.com:27017[mongodb://user:password@something.example.com:27017/db]'
[2016-04-01T16:16:00+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1220
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():383
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():389
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   > TRACE: mongoc_topology_description_handle_ismaster():1400 No transition entry to 4 for 0
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_select():493
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_select():507
[2016-04-01T16:16:00+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_stream_for_optype():1670
[2016-04-01T16:16:00+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_fetch_stream():322
[2016-04-01T16:16:00+00:00]     cursor: TRACE   >  GOTO: _mongoc_cursor_initial_query():353 done
[2016-04-01T16:16:00+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_initial_query():382
[2016-04-01T16:16:00+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_next():1079
[2016-04-01T16:16:00+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_next():1000
[2016-04-01T16:16:00+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_error():923
[2016-04-01T16:16:00+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_error():941
[2016-04-01T16:16:00+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_error():951
[2016-04-01T16:16:00+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_error():933
[2016-04-01T16:16:00+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_destroy():242
[2016-04-01T16:16:00+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_destroy():259
[2016-04-01T16:16:00+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_destroy():296
[2016-04-01T16:16:00+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_destroy():252
[2016-04-01T16:16:00+00:00] PHONGO-BSON: TRACE   > Added new _id
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   > ENTRY: mongoc_bulk_operation_insert():205
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_command_init_insert():176
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_command_insert_append():72
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_command_insert_append():102
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_command_init_insert():192
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   >  EXIT: mongoc_bulk_operation_insert():227
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   > ENTRY: mongoc_bulk_operation_execute():372
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_result_init():1007
[2016-04-01T16:16:00+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_result_init():1017
[2016-04-01T16:16:00+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_stream_for_optype():1658
[2016-04-01T16:16:01+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1170
[2016-04-01T16:16:01+00:00]     PHONGO: DEBUG   > Connecting to 'something.example.com:27017[mongodb://user:password@something.example.com:27017/db]'
[2016-04-01T16:16:11+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1220
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():383
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():389
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   > TRACE: mongoc_topology_description_handle_ismaster():1400 No transition entry to 4 for 0
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_select():493
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_select():507
[2016-04-01T16:16:11+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_stream_for_optype():1670
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   >  EXIT: mongoc_bulk_operation_execute():431
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_result_destroy():1024
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_result_destroy():1032
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_command_destroy():994
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_command_destroy():1000
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_result_destroy():1024
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_result_destroy():1032

"Exception: "
"MongoDB\\Driver\\Exception\\ConnectionTimeoutException:No suitable servers found (`serverselectiontryonce` set): [Failed connecting to 'something.example.com:27017': php_network_getaddresses: getaddrinfo failed: Name or service not known]\nMongoDB\\Driver\\Exception\\ConnectionTimeoutException:No suitable servers found (`serverselectiontryonce` set): [Failed connecting to 'something.example.com:27017': php_network_getaddresses: getaddrinfo failed: Name or service not known]\nMongoDB\\Driver\\Exception\\ConnectionTimeoutException:No suitable servers found (`serverselectiontryonce` set): [Failed connecting to 'something.example.com:27017': php_network_getaddresses: getaddrinfo failed: Name or service not known]"
"exec_time": "36451.321 ms"

[2016-04-01T16:16:11+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_destroy():89
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2016-04-01T16:16:11+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_destroy():103
[2016-04-01T16:16:11+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_destroy():1616
[2016-04-01T16:16:11+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_destroy():1626

real    0m36.505s
user    0m0.012s
sys 0m0.012s
jmikola commented 8 years ago

@zachrattner: Based on the logs, you have three distinct timeout events, each of which takes ten seconds:

[2016-04-01T16:15:35+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1170
[2016-04-01T16:15:35+00:00]     PHONGO: DEBUG   > Connecting to 'something.example.com:27017[mongodb://user:password@something.example.com:27017/db]'
[2016-04-01T16:15:50+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1220

[2016-04-01T16:15:50+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1170
[2016-04-01T16:15:50+00:00]     PHONGO: DEBUG   > Connecting to 'something.example.com:27017[mongodb://user:password@something.example.com:27017/db]'
[2016-04-01T16:16:00+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1220

[2016-04-01T16:16:01+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1170
[2016-04-01T16:16:01+00:00]     PHONGO: DEBUG   > Connecting to 'something.example.com:27017[mongodb://user:password@something.example.com:27017/db]'
[2016-04-01T16:16:11+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1220

By cross-referencing the line numbers for ENTRY and EXIT with the 1.1.5 sources, it's clear that phongo_stream_initiator is returning after php_stream_xport_create() fails (i.e. returns a null stream pointer). This is where the "Failed connecting to '[host]:[port]'" error message is constructed, which ultimately gets included in the ConnectionTimeoutException message. The socket connection occurs within the driver's attempt to select a server for the operation, which is why it's embedded in another message.

What is the exact test.php file being used to generate the above trace? The following line in your output log looks like a jumble of three separate exceptions (despite appearing on the same line):

"Exception: "
"MongoDB\\Driver\\Exception\\ConnectionTimeoutException:No suitable servers found (`serverselectiontryonce` set): [Failed connecting to 'something.example.com:27017': php_network_getaddresses: getaddrinfo failed: Name or service not known]\nMongoDB\\Driver\\Exception\\ConnectionTimeoutException:No suitable servers found (`serverselectiontryonce` set): [Failed connecting to 'something.example.com:27017': php_network_getaddresses: getaddrinfo failed: Name or service not known]\nMongoDB\\Driver\\Exception\\ConnectionTimeoutException:No suitable servers found (`serverselectiontryonce` set): [Failed connecting to 'something.example.com:27017': php_network_getaddresses: getaddrinfo failed: Name or service not known]"
"exec_time": "36451.321 ms"

Are you attempting three operations in sequence, each of which catches and prints an exception message? Alternatively, are you appending the messages in a string and dumping them once?

If each connection timeout takes ten seconds, I expect that either connectTimeoutMS is set to 10000 (and it is being applied correctly) or it was not set and PHP is defaulting to default_socket_timeout, which is typically 60 seconds but may be changed in your environment. I would expect the process to block for the full timeout duration if the host cannot be reached at all (as you said) When the host is accessible but not listening on a port, it can still respond immediately to reject the connection.

zachrattner commented 8 years ago

Sorry about the triple-posting issue -- I dug into it and that particular issue was with my app code. I rewrote a bare bones test script from scratch to isolate the issue and the sample below still seems to ignore the connect timeout when the hostname is invalid. For what it's worth, default_socket_timeout is 60.

Here is the command I used to generate the logs:

php test.php &> log.txt

test.php

<?php

ini_set('mongodb.debug', 'stderr');

$connStr = sprintf
(
    'mongodb://%s:%s@%s:%d/%s',
     'user',
     'pass',
     'something.example.com', // invalid
     27017,
     'database'
);

$opts = ['connecttimeoutms' => 100000]; // this line doesn't matter (1000, 10000, 100000 all same)
$conn = new \MongoDB\Driver\Manager($connStr, $opts);

$namespace = 'database.Collection';
$filter    = ['name' => 'Something'];

$query = new \MongoDB\Driver\Query($filter);
$cursor = $conn->executeQuery($namespace, $query);

// Dump the objects
foreach ($cursor as $doc)
{
    $doc = get_object_vars($doc);
    var_dump($doc);
}

?>

log.txt

[2016-04-04T22:38:38+00:00]     PHONGO: DEBUG   > Connection string: 'mongodb://user:pass@something.example.com:27017/database'
[2016-04-04T22:38:38+00:00]     PHONGO: TRACE   > ENTRY: php_phongo_make_mongo_client():1944
[2016-04-04T22:38:38+00:00]     PHONGO: DEBUG   > Creating Manager, phongo-1.1.5[stable] - mongoc-1.3.3(bundled), libbson-1.3.3(bundled), php-7.0.5
[2016-04-04T22:38:38+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_init():51
[2016-04-04T22:38:38+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_init():68
[2016-04-04T22:38:38+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_init():87
[2016-04-04T22:38:38+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_init():123
[2016-04-04T22:38:38+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_init():1570
[2016-04-04T22:38:38+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_init():1593
[2016-04-04T22:38:38+00:00]     client: DEBUG   > Using custom stream initiator.
[2016-04-04T22:38:38+00:00]     PHONGO: TRACE   >  EXIT: php_phongo_make_mongo_client():2042
[2016-04-04T22:38:38+00:00] collection: TRACE   > ENTRY: _mongoc_collection_new():170
[2016-04-04T22:38:38+00:00] collection: TRACE   >  EXIT: _mongoc_collection_new():199
[2016-04-04T22:38:38+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_new():85
[2016-04-04T22:38:38+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_new():235
[2016-04-04T22:38:38+00:00] collection: TRACE   > ENTRY: mongoc_collection_destroy():223
[2016-04-04T22:38:38+00:00] collection: TRACE   >  EXIT: mongoc_collection_destroy():248
[2016-04-04T22:38:38+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_next():964
[2016-04-04T22:38:38+00:00]     cursor: TRACE   > TRACE: mongoc_cursor_next():969 cursor_id(0)
[2016-04-04T22:38:38+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_next():1025
[2016-04-04T22:38:38+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_initial_query():346
[2016-04-04T22:38:38+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_fetch_stream():305
[2016-04-04T22:38:38+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_stream_for_optype():1658
[2016-04-04T22:38:38+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1170
[2016-04-04T22:38:38+00:00]     PHONGO: DEBUG   > Connecting to 'something.example.com:27017[mongodb://user:pass@something.example.com:27017/database]'
[2016-04-04T22:38:53+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1220
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():383
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():389
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   > TRACE: mongoc_topology_description_handle_ismaster():1400 No transition entry to 4 for 0
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_select():493
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_select():507
[2016-04-04T22:38:53+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_stream_for_optype():1670
[2016-04-04T22:38:53+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_fetch_stream():322
[2016-04-04T22:38:53+00:00]     cursor: TRACE   >  GOTO: _mongoc_cursor_initial_query():353 done
[2016-04-04T22:38:53+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_initial_query():382
[2016-04-04T22:38:53+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_next():1079
[2016-04-04T22:38:53+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_next():1000
[2016-04-04T22:38:53+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_error():923
[2016-04-04T22:38:53+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_error():941
[2016-04-04T22:38:53+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_error():951
[2016-04-04T22:38:53+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_error():933
[2016-04-04T22:38:53+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_destroy():242
[2016-04-04T22:38:53+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_destroy():259
[2016-04-04T22:38:53+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_destroy():296
[2016-04-04T22:38:53+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_destroy():252
PHP Fatal error:  Uncaught MongoDB\Driver\Exception\ConnectionTimeoutException: No suitable servers found (`serverselectiontryonce` set): [Failed connecting to 'something.example.com:27017': php_network_getaddresses: getaddrinfo failed: Name or service not known] in test.php:23
Stack trace:
#0 test.php(23): MongoDB\Driver\Manager->executeQuery('database.Collection', Object(MongoDB\Driver\Query))
#1 {main}
  thrown in test.php on line 23

Fatal error: Uncaught MongoDB\Driver\Exception\ConnectionTimeoutException: No suitable servers found (`serverselectiontryonce` set): [Failed connecting to 'something.example.com:27017': php_network_getaddresses: getaddrinfo failed: Name or service not known] in test.php:23
Stack trace:
#0 test.php(23): MongoDB\Driver\Manager->executeQuery('database.Collection', Object(MongoDB\Driver\Query))
#1 {main}
  thrown in test.php on line 23
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_destroy():89
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_destroy():103
[2016-04-04T22:38:53+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_destroy():1616
[2016-04-04T22:38:53+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_destroy():1626
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_destroy():89
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2016-04-04T22:38:53+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_destroy():103
[2016-04-04T22:38:53+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_destroy():1616
[2016-04-04T22:38:53+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_destroy():1626

real    0m15.084s
user    0m0.000s
sys     0m0.012s
pinkladywithcoco commented 8 years ago

any news? its have been a while now and this is a very urgent bug...

jmikola commented 8 years ago

I was not able to reproduce this when connecting to an invalid hostname (e.g. something.example.com). In my tests, the connection immediately failed with the same exception that @zachrattner saw above. The relevant timing information from my debug logs is:

[2016-06-23T15:02:42+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1142
[2016-06-23T15:02:42+00:00]     PHONGO: DEBUG   > Connecting to 'something.example.com:27017[mongodb://something.example.com:27017]'
[2016-06-23T15:02:42+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1193

I decided to create an actual network black hole using iptables:

$ sudo iptables -I INPUT -p tcp -d 127.0.0.1 --dpor 27018 -j DROP

Note: this can be reverted later with iptables -D INPUT and the same, remaining arguments.

This causes all traffic destined to 127.0.01:27018 to drop entirely, which I believe is effective for testing a true connection timeout. With this filter in place, I changed the connection URI in my script to "mongodb://127.0.0.1:27018" and ran several tests on both 1.1.5 and 1.1.7 (which includes extra debugging to report the applied "connecttimeoutms" option):

Here was my test script, which I ran with php test.php &> log.txt to collect output:

<?php

ini_set('mongodb.debug', 'stderr');

$manager = new MongoDB\Driver\Manager(
    'mongodb://127.0.0.1:27018',
    [ 'connecttimeoutms' => 1000]
);

$command = new MongoDB\Driver\Command(['ping' => 1]);
$cursor = $manager->executeCommand('test', $command);
var_dump($cursor->toArray()[0]);

Results were as follows:

1.1.5 with connecttimeoutms=1000
[2016-06-23T14:44:33+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1170
[2016-06-23T14:44:33+00:00]     PHONGO: DEBUG   > Connecting to '127.0.0.1:27018[mongodb://127.0.0.1:27018]'
[2016-06-23T14:44:34+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1220

1.1.5 with connecttimeoutms=10000
[2016-06-23T14:45:16+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1170
[2016-06-23T14:45:16+00:00]     PHONGO: DEBUG   > Connecting to '127.0.0.1:27018[mongodb://127.0.0.1:27018]'
[2016-06-23T14:45:26+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1220

1.1.5 with connecttimeoutms=100000
[2016-06-23T14:46:36+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1170
[2016-06-23T14:46:36+00:00]     PHONGO: DEBUG   > Connecting to '127.0.0.1:27018[mongodb://127.0.0.1:27018]'
[2016-06-23T14:48:16+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1220

1.1.5 with no options (default_socket_timeout=60)
[2016-06-23T14:48:53+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1170
[2016-06-23T14:48:53+00:00]     PHONGO: DEBUG   > Connecting to '127.0.0.1:27018[mongodb://127.0.0.1:27018]'
[2016-06-23T14:49:53+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1220

1.1.7 with connecttimeoutms=1000
[2016-06-23T14:57:25+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1142
[2016-06-23T14:57:25+00:00]     PHONGO: DEBUG   > Applying connectTimeoutMS: 1000
[2016-06-23T14:57:25+00:00]     PHONGO: DEBUG   > Connecting to '127.0.0.1:27018[mongodb://127.0.0.1:27018]'
[2016-06-23T14:57:26+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1193

1.1.7 with connecttimeoutms=10000
[2016-06-23T14:55:40+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1142
[2016-06-23T14:55:40+00:00]     PHONGO: DEBUG   > Applying connectTimeoutMS: 10000
[2016-06-23T14:55:40+00:00]     PHONGO: DEBUG   > Connecting to '127.0.0.1:27018[mongodb://127.0.0.1:27018]'
[2016-06-23T14:55:50+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1193

1.1.7 with connecttimeoutms=100000
[2016-06-23T14:53:44+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1142
[2016-06-23T14:53:44+00:00]     PHONGO: DEBUG   > Applying connectTimeoutMS: 100000
[2016-06-23T14:53:44+00:00]     PHONGO: DEBUG   > Connecting to '127.0.0.1:27018[mongodb://127.0.0.1:27018]'
[2016-06-23T14:55:24+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1193

1.1.7 with no options (default_socket_timeout=60)
[2016-06-23T14:57:40+00:00]     PHONGO: TRACE   > ENTRY: phongo_stream_initiator():1142
[2016-06-23T14:57:40+00:00]     PHONGO: DEBUG   > Connecting to '127.0.0.1:27018[mongodb://127.0.0.1:27018]'
[2016-06-23T14:58:40+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1193

Are these results reproducible for you?

jmikola commented 8 years ago

1.2.0alpha2 of the driver has been released, which includes significant changes to our connection handling and persistence. We've entirely dropped PHP's streams API and now rely on libmongoc for all socket communication, which I expect may resolve a number of outstanding connection handling and timeout issues.

@zachrattner: Please attempt reproducing your original problem with 1.2.0alpha2 and let us know if the issue persists. Thanks!

jmikola commented 7 years ago

@zachrattner: 1.2.0 of the extension has been released. I'm going to close this out, but please follow up if the issue persists after upgrading the extension and I'll look into it further.

cbanbury commented 5 years ago

I'm seeing exactly this issue in 1.4.

Adding socketTimeoutMS directly into the mongo uri works as expected, but is ignored when passed as an option. Using the example from the op:

Works:

$manager = new MongoDB\Driver\Manager('mongodb://user:pass@host:port/db?socketTimeoutMS=1000');

Fails:

$opts = ['socketTimeoutMS' => 1000];
$manager = new MongoDB\Driver\Manager('mongodb://user:pass@host:port/db', $opts);
jmikola commented 5 years ago

@cbanbury: Please open a new issue rather than continue discussion in a closed ticket. Feel free to link back to this thread for context. Additionally, it'd be helpful if you can provide a reproducible script that demonstrates the option not being respected. This should be easy to accomplish by executing a basic find query using the $where operator and a sleep statement in JavaScript (see: https://stackoverflow.com/a/16848240/162228) to surpass the expected socket timeout.