[SERVER-35762] Empty $clusterTime document Created: 22/Jun/18  Updated: 27/Oct/23  Resolved: 23/Jun/18

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: 3.6.5, 4.0.0-rc5
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: David Golden Assignee: [DO NOT USE] Backlog - Sharding Team
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

RHEL62, Windows


Assigned Teams:
Sharding
Operating System: ALL
Participants:

 Description   

While testing the Perl driver, I noticed intermittent cases where an isMaster request to a replica set returns an empty document for $clustertime.

The failures include command monitoring output, which has results like this (truncated):

 [2018/06/22 13:27:23.973]         # [
 [2018/06/22 13:27:23.973]         #   {
 [2018/06/22 13:27:23.973]         #     'command' => {
 [2018/06/22 13:27:23.973]         #       'client' => {
 [2018/06/22 13:27:23.973]         #         'driver' => {
 [2018/06/22 13:27:23.973]         #           'name' => 'MongoDB Perl Driver',
 [2018/06/22 13:27:23.973]         #           'version' => '1.999.1'
 [2018/06/22 13:27:23.973]         #         },
 [2018/06/22 13:27:23.973]         #         'os' => {
 [2018/06/22 13:27:23.973]         #           'type' => 'Windows'
 [2018/06/22 13:27:23.973]         #         },
 [2018/06/22 13:27:23.973]         #         'platform' => 'Perl v5.24.3 MSWin32-x64-multi-thread'
 [2018/06/22 13:27:23.973]         #       },
 [2018/06/22 13:27:23.973]         #       'ismaster' => 1
 [2018/06/22 13:27:23.973]         #     },
 [2018/06/22 13:27:23.973]         #     'commandName' => 'ismaster',
 [2018/06/22 13:27:23.973]         #     'connectionId' => 'localhost:27019',
 [2018/06/22 13:27:23.973]         #     'databaseName' => 'admin',
 [2018/06/22 13:27:23.973]         #     'requestId' => 1506792765,
 [2018/06/22 13:27:23.973]         #     'type' => 'command_started'
 [2018/06/22 13:27:23.973]         #   },
 [2018/06/22 13:27:23.973]         #   {
 [2018/06/22 13:27:23.973]         #     'commandName' => 'ismaster',
 [2018/06/22 13:27:23.974]         #     'connectionId' => 'localhost:27019',
 [2018/06/22 13:27:23.974]         #     'databaseName' => 'admin',
 [2018/06/22 13:27:23.974]         #     'durationSecs' => '0.00038599967956543',
 [2018/06/22 13:27:23.974]         #     'reply' => {
 [2018/06/22 13:27:23.974]         #       '$clusterTime' => {},
 [2018/06/22 13:27:23.974]         #       'arbiterOnly' => bless( do{\(my $o = 1)}, 'boolean' ),
 [2018/06/22 13:27:23.974]         #       'arbiters' => [
 [2018/06/22 13:27:23.974]         #         'localhost:27019'
 [2018/06/22 13:27:23.974]         #       ],
 [2018/06/22 13:27:23.974]         #       'hosts' => [
 [2018/06/22 13:27:23.974]         #         'localhost:27017',
 [2018/06/22 13:27:23.974]         #         'localhost:27018'
 [2018/06/22 13:27:23.974]         #       ],
 [2018/06/22 13:27:23.974]         #       'ismaster' => bless( do{\(my $o = 0)}, 'boolean' ),
 [2018/06/22 13:27:23.974]         #       'lastWrite' => {
 [2018/06/22 13:27:23.974]         #         'lastWriteDate' => bless( {
 [2018/06/22 13:27:23.974]         #           'value' => '1529688442000'
 [2018/06/22 13:27:23.974]         #         }, 'BSON::Time' ),
 [2018/06/22 13:27:23.974]         #         'majorityOpTime' => {
 [2018/06/22 13:27:23.974]         #           't' => 1,
 [2018/06/22 13:27:23.974]         #           'ts' => bless( {
 [2018/06/22 13:27:23.974]         #             'increment' => 402,
 [2018/06/22 13:27:23.974]         #             'seconds' => 1529688442
 [2018/06/22 13:27:23.974]         #           }, 'BSON::Timestamp' )
 [2018/06/22 13:27:23.974]         #         },
 [2018/06/22 13:27:23.974]         #         'majorityWriteDate' => bless( {
 [2018/06/22 13:27:23.974]         #           'value' => '1529688442000'
 [2018/06/22 13:27:23.974]         #         }, 'BSON::Time' ),
 [2018/06/22 13:27:23.974]         #         'opTime' => {
 [2018/06/22 13:27:23.974]         #           't' => 1,
 [2018/06/22 13:27:23.974]         #           'ts' => bless( {
 [2018/06/22 13:27:23.974]         #             'increment' => 402,
 [2018/06/22 13:27:23.974]         #             'seconds' => 1529688442
 [2018/06/22 13:27:23.974]         #           }, 'BSON::Timestamp' )
 [2018/06/22 13:27:23.974]         #         }
 [2018/06/22 13:27:23.974]         #       },
 [2018/06/22 13:27:23.974]         #       'localTime' => bless( {
 [2018/06/22 13:27:23.974]         #         'value' => '1529688443956'
 [2018/06/22 13:27:23.974]         #       }, 'BSON::Time' ),
 [2018/06/22 13:27:23.974]         #       'logicalSessionTimeoutMinutes' => 30,
 [2018/06/22 13:27:23.974]         #       'maxBsonObjectSize' => 16777216,
 [2018/06/22 13:27:23.974]         #       'maxMessageSizeBytes' => 48000000,
 [2018/06/22 13:27:23.974]         #       'maxWireVersion' => 7,
 [2018/06/22 13:27:23.974]         #       'maxWriteBatchSize' => 100000,
 [2018/06/22 13:27:23.974]         #       'me' => 'localhost:27019',
 [2018/06/22 13:27:23.974]         #       'minWireVersion' => 0,
 [2018/06/22 13:27:23.974]         #       'ok' => '1',
 [2018/06/22 13:27:23.974]         #       'primary' => 'localhost:27017',
 [2018/06/22 13:27:23.974]         #       'readOnly' => $VAR1->[1]{'reply'}{'ismaster'},
 [2018/06/22 13:27:23.974]         #       'secondary' => $VAR1->[1]{'reply'}{'ismaster'},
 [2018/06/22 13:27:23.974]         #       'setName' => 'repl0',
 [2018/06/22 13:27:23.974]         #       'setVersion' => 1
 [2018/06/22 13:27:23.974]         #     },
 [2018/06/22 13:27:23.974]         #     'requestId' => 1506792765,
 [2018/06/22 13:27:23.974]         #     'type' => 'command_succeeded'
 [2018/06/22 13:27:23.974]         #   },

I observed this on 3.6, 4.0-rc5 and 4.1.0 (latest) – all running without auth. It's not consistent, for example in the patch build linked above, two of the tasks had no error. Over various patch builds (with less diagnostic output), I saw similar failures with no pattern as to which version/platform succeeds or fails.

A patch that explicitly ignores empty $clusterTime documents in replies gets the driver tests passing always.



 Comments   
Comment by David Golden [ 23/Jun/18 ]

That says that arbiters omit $clusterTime and the failure examples I included was from an arbiter. It's very likely that in that case, the empty $clusterTime document could be an artifact of a Perl feature that auto-creates hashes when trying to access keys. I'll close this ticket.

Generated at Thu Feb 08 04:40:52 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.