-
Type:
Bug
-
Resolution: Works as Designed
-
Priority:
Major - P3
-
None
-
Affects Version/s: 3.6.5, 4.0.0-rc5
-
Component/s: Sharding
-
Labels:None
-
Environment:RHEL62, Windows
-
Sharding
-
ALL
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.