Uploaded image for project: 'PHP Legacy Driver'
  1. PHP Legacy Driver
  2. PHP-1500

Socket timeout not applied to initial command cursor query

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Fixed
    • Affects Version/s: 1.6.11, 1.6.12
    • Fix Version/s: 1.6.13
    • Component/s: pecl-mongo
    • Labels:
      None
    • Environment:
      PHP 5.4.16 Apache 2.0 Handler
      Apache/2.4.6 (CentOS)
      Linux foobar 3.10.0-229.20.1.el7.x86_64 #1 SMP Tue Nov 3 19:10:07 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
      Mongod 3.0.5
    • # Replies:
      4
    • Last comment by Customer:
      true

      Description

      Given the following:

      $mongo = new \MongoClient( 'localhost/mydb', array(
        'connect' => true,
      ));
      $collection = $mongo->selectCollection( 'mydb', 'mycollection' );
      $pipeline = ... ;
      $cursor = $collection->aggregateCursor( $pipeline );
      $cursor->timeout( 120000 );
      $cursor->rewind(); // exception here
      

      I get the following exception: exception 'MongoCursorTimeoutException' with message 'localhost:27017: Read timed out after reading 0 bytes, waited for 30.000000 seconds' in ...

      I've enabled MongoLog just before the query using the following code:

      \MongoLog::setLevel(\MongoLog::ALL);
      \MongoLog::setModule(\MongoLog::ALL);
      \MongoLog::setCallback(function($module, $level, $message)
      {
        static $logFile = false;
       
        if (!$logFile) {
          $logFile = "/storage/MONGO-PHP-LOG." . time();
          error_log('REQUEST_URI: ' . $_SERVER['REQUEST_URI'], 3, $logFile);
        }
       
        switch ($module) {
          case \MongoLog::RS: $module = "REPLSET"; break;
          case \MongoLog::CON: $module = "CON"; break;
          case \MongoLog::IO: $module = "IO"; break;
          case \MongoLog::SERVER: $module = "SERVER"; break;
          case \MongoLog::PARSE: $module = "PARSE"; break;
        }
       
        switch ($level) {
          case \MongoLog::WARNING: $level = "WARN"; break;
          case \MongoLog::INFO: $level = "INFO"; break;
          case \MongoLog::FINE: $level = "FINE"; break;
          default: return $level;
        }
       
        $log = sprintf("%s :: %s (%s): %s\n", date('Y-m-d H:i:s',time()), $module, $level, $message);
       
        error_log($log, 3, $logFile);
      });
      

      Which gives me the following:

      2015-12-03 15:07:22 :: CON (FINE): Initializing cursor timeout to 30000 (from connection options)
      2015-12-03 15:07:22 :: CON (INFO): command supports Read Preferences
      2015-12-03 15:07:22 :: CON (INFO): mongo_get_read_write_connection: finding a STANDALONE connection
      2015-12-03 15:07:22 :: CON (FINE): found connection localhost:27017;-;.;32038 (looking for localhost:27017;-;.;32038)
      2015-12-03 15:07:22 :: CON (FINE): is_ping: skipping: last ran at 1449155241, now: 1449155242, time left: 4
      2015-12-03 15:07:22 :: CON (FINE): ismaster: skipping: last ran at 1449155241, now: 1449155242, time left: 14
      2015-12-03 15:07:22 :: REPLSET (FINE): finding candidate servers
      2015-12-03 15:07:22 :: REPLSET (FINE): - all servers
      2015-12-03 15:07:22 :: REPLSET (FINE): - collect any
      2015-12-03 15:07:22 :: REPLSET (FINE): filter_connections: adding connections:
      2015-12-03 15:07:22 :: REPLSET (FINE): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:22 :: REPLSET (FINE): filter_connections: done
      2015-12-03 15:07:22 :: REPLSET (FINE): limiting by seeded/discovered servers
      2015-12-03 15:07:22 :: REPLSET (FINE): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:22 :: REPLSET (FINE): limiting by seeded/discovered servers: done
      2015-12-03 15:07:22 :: REPLSET (FINE): limiting by credentials
      2015-12-03 15:07:22 :: REPLSET (FINE): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:22 :: REPLSET (FINE): limiting by credentials: done
      2015-12-03 15:07:22 :: REPLSET (FINE): sorting servers by priority and ping time
      2015-12-03 15:07:22 :: REPLSET (FINE): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:22 :: REPLSET (FINE): sorting servers: done
      2015-12-03 15:07:22 :: REPLSET (FINE): selecting near servers
      2015-12-03 15:07:22 :: REPLSET (FINE): selecting near servers: nearest is 0ms
      2015-12-03 15:07:22 :: REPLSET (FINE): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:22 :: REPLSET (FINE): selecting near server: done
      2015-12-03 15:07:22 :: REPLSET (INFO): pick server: random element 0
      2015-12-03 15:07:22 :: REPLSET (INFO): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:22 :: IO (FINE): getting reply
      2015-12-03 15:07:22 :: IO (FINE): getting cursor header
      2015-12-03 15:07:22 :: CON (FINE): No timeout changes for localhost:27017;-;.;32038
      2015-12-03 15:07:52 :: CON (INFO): mongo_get_read_write_connection: finding a STANDALONE connection
      2015-12-03 15:07:52 :: CON (INFO): connection_create: creating new connection for localhost:27017
      2015-12-03 15:07:52 :: CON (FINE): Connecting to tcp://localhost:27017 (localhost:27017;-;.;32038) with connection timeout: 60.000000
      2015-12-03 15:07:52 :: CON (INFO): stream_connect: Not establishing SSL for localhost:27017
      2015-12-03 15:07:52 :: CON (FINE): Setting stream timeout to 30.000000
      2015-12-03 15:07:52 :: CON (INFO): ismaster: start
      2015-12-03 15:07:52 :: CON (FINE): Setting the stream timeout to 60.000000
      2015-12-03 15:07:52 :: CON (FINE): Now setting stream timeout back to 30.000000
      2015-12-03 15:07:52 :: CON (FINE): send_packet: read from header: 36
      2015-12-03 15:07:52 :: CON (FINE): send_packet: data_size: 158
      2015-12-03 15:07:52 :: CON (FINE): Setting the stream timeout to 60.000000
      2015-12-03 15:07:52 :: CON (FINE): Now setting stream timeout back to 30.000000
      2015-12-03 15:07:52 :: CON (FINE): ismaster: setting minWireVersion to 0
      2015-12-03 15:07:52 :: CON (FINE): ismaster: setting maxWireVersion to 3
      2015-12-03 15:07:52 :: CON (FINE): ismaster: setting maxBsonObjectSize to 16777216
      2015-12-03 15:07:52 :: CON (FINE): ismaster: setting maxMessageSizeBytes to 48000000
      2015-12-03 15:07:52 :: CON (FINE): ismaster: setting maxWriteBatchSize to 1000
      2015-12-03 15:07:52 :: CON (INFO): ismaster: set name: (null), ismaster: 1, secondary: 0, is_arbiter: 0
      2015-12-03 15:07:52 :: CON (INFO): ismaster: last ran at 1449155272
      2015-12-03 15:07:52 :: CON (INFO): get_server_version: start
      2015-12-03 15:07:52 :: CON (FINE): Setting the stream timeout to 60.000000
      2015-12-03 15:07:52 :: CON (FINE): Now setting stream timeout back to 30.000000
      2015-12-03 15:07:52 :: CON (FINE): send_packet: read from header: 36
      2015-12-03 15:07:52 :: CON (FINE): send_packet: data_size: 764
      2015-12-03 15:07:52 :: CON (FINE): Setting the stream timeout to 60.000000
      2015-12-03 15:07:52 :: CON (FINE): Now setting stream timeout back to 30.000000
      2015-12-03 15:07:52 :: CON (INFO): get_server_version: server version: 3.0.5 (0)
      2015-12-03 15:07:52 :: CON (INFO): is_ping: pinging localhost:27017;-;.;32038
      2015-12-03 15:07:52 :: CON (FINE): Setting the stream timeout to 60.000000
      2015-12-03 15:07:52 :: CON (FINE): Now setting stream timeout back to 30.000000
      2015-12-03 15:07:52 :: CON (FINE): send_packet: read from header: 36
      2015-12-03 15:07:52 :: CON (FINE): send_packet: data_size: 17
      2015-12-03 15:07:52 :: CON (FINE): Setting the stream timeout to 60.000000
      2015-12-03 15:07:52 :: CON (FINE): Now setting stream timeout back to 30.000000
      2015-12-03 15:07:52 :: CON (INFO): is_ping: last pinged at 1449155272; time: 0ms
      2015-12-03 15:07:52 :: CON (FINE): ismaster: skipping: last ran at 1449155272, now: 1449155272, time left: 15
      2015-12-03 15:07:52 :: REPLSET (FINE): finding candidate servers
      2015-12-03 15:07:52 :: REPLSET (FINE): - all servers
      2015-12-03 15:07:52 :: REPLSET (FINE): - collect any
      2015-12-03 15:07:52 :: REPLSET (FINE): filter_connections: adding connections:
      2015-12-03 15:07:52 :: REPLSET (FINE): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:52 :: REPLSET (FINE): filter_connections: done
      2015-12-03 15:07:52 :: REPLSET (FINE): limiting by seeded/discovered servers
      2015-12-03 15:07:52 :: REPLSET (FINE): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:52 :: REPLSET (FINE): limiting by seeded/discovered servers: done
      2015-12-03 15:07:52 :: REPLSET (FINE): limiting by credentials
      2015-12-03 15:07:52 :: REPLSET (FINE): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:52 :: REPLSET (FINE): limiting by credentials: done
      2015-12-03 15:07:52 :: REPLSET (FINE): sorting servers by priority and ping time
      2015-12-03 15:07:52 :: REPLSET (FINE): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:52 :: REPLSET (FINE): sorting servers: done
      2015-12-03 15:07:52 :: REPLSET (FINE): selecting near servers
      2015-12-03 15:07:52 :: REPLSET (FINE): selecting near servers: nearest is 0ms
      2015-12-03 15:07:52 :: REPLSET (FINE): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:52 :: REPLSET (FINE): selecting near server: done
      2015-12-03 15:07:52 :: REPLSET (INFO): pick server: random element 0
      2015-12-03 15:07:52 :: REPLSET (INFO): - connection: type: STANDALONE, socket: 42, ping: 0, hash: localhost:27017;-;.;32038
      2015-12-03 15:07:52 :: CON (FINE): No timeout changes for localhost:27017;-;.;32038
      2015-12-03 15:07:52 :: CON (FINE): No timeout changes for localhost:27017;-;.;32038
      

        Attachments

          Activity

            People

            Assignee:
            jmikola Jeremy Mikola
            Reporter:
            jorisw Joris van der Wel
            Participants:
            Last commenter:
            Alexander Golin
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:
              Days since reply:
              4 years, 28 weeks, 3 days ago
              Date of 1st Reply: