SERVER-31306 include clusterTime and operationTime in all errors

3 files changed, 80 insertions, 11 deletions

diff --git a/jstests/sharding/logical_time_metadata.js b/jstests/sharding/logical_time_metadata.js
index 63d3fc57cef..4d52fc3bb4f 100644
--- a/jstests/sharding/logical_time_metadata.js
+++ b/jstests/sharding/logical_time_metadata.js
@@ -4,21 +4,34 @@
  * where the cluster time metadata can propagated, making it inherently racy.
  */
 (function() {
+    "use strict";
+
+    function assertHasClusterTimeAndOperationTime(res) {
+        assert.hasFields(res, ['$clusterTime']);
+        assert.hasFields(res.$clusterTime, ['clusterTime', 'signature']);
+    }
+
     var st = new ShardingTest({shards: {rs0: {nodes: 3}}, mongosWaitsForKeys: true});
     st.s.adminCommand({enableSharding: 'test'});
 
     var db = st.s.getDB('test');
 
-    // insert on one shard and extract the cluster time
-    var res = assert.commandWorked(db.runCommand({insert: 'user', documents: [{x: 10}]}));
-    assert.hasFields(res, ['$clusterTime']);
+    var res = db.runCommand({insert: 'user', documents: [{x: 10}]});
+    assert.commandWorked(res);
+    assertHasClusterTimeAndOperationTime(res);
 
-    var logicalTimeMetadata = res.$clusterTime;
-    assert.hasFields(logicalTimeMetadata, ['clusterTime', 'signature']);
+    res = db.runCommand({blah: 'blah'});
+    assert.commandFailed(res);
+    assertHasClusterTimeAndOperationTime(res);
+
+    res = db.runCommand({insert: "user", documents: [{x: 10}], writeConcern: {blah: "blah"}});
+    assert.commandFailed(res);
+    assertHasClusterTimeAndOperationTime(res);
 
     res = st.rs0.getPrimary().adminCommand({replSetGetStatus: 1});
 
     var appliedTime = res.optimes.appliedOpTime.ts;
+    var logicalTimeMetadata = res.$clusterTime;
     assert.eq(0,
               timestampCmp(appliedTime, logicalTimeMetadata.clusterTime),
               'appliedTime: ' + tojson(appliedTime) + ' != clusterTime: ' +
@@ -26,6 +39,19 @@
 
     assert.commandWorked(db.runCommand({ping: 1, '$clusterTime': logicalTimeMetadata}));
 
+    db = st.rs0.getPrimary().getDB('testRS');
+    res = db.runCommand({insert: 'user', documents: [{x: 10}]});
+    assert.commandWorked(res);
+    assertHasClusterTimeAndOperationTime(res);
+
+    res = db.runCommand({blah: 'blah'});
+    assert.commandFailed(res);
+    assertHasClusterTimeAndOperationTime(res);
+
+    res = db.runCommand({insert: "user", documents: [{x: 10}], writeConcern: {blah: "blah"}});
+    assert.commandFailed(res);
+    assertHasClusterTimeAndOperationTime(res);
+
     st.stop();
 
 })();
diff --git a/src/mongo/db/service_entry_point_mongod.cpp b/src/mongo/db/service_entry_point_mongod.cpp
index d0c2e449646..fb93a273413 100644
--- a/src/mongo/db/service_entry_point_mongod.cpp
+++ b/src/mongo/db/service_entry_point_mongod.cpp
@@ -251,6 +251,31 @@ private:
     const bool _maintenanceModeSet;
 };
 
+// Called from the error contexts where request may not be available.
+// It only attaches clusterTime and operationTime.
+void appendReplyMetadataOnError(OperationContext* opCtx, BSONObjBuilder* metadataBob) {
+    auto const replCoord = repl::ReplicationCoordinator::get(opCtx);
+    const bool isReplSet =
+        replCoord->getReplicationMode() == repl::ReplicationCoordinator::modeReplSet;
+
+    if (isReplSet) {
+        if (serverGlobalParams.featureCompatibility.isFullyUpgradedTo36()) {
+            if (LogicalTimeValidator::isAuthorizedToAdvanceClock(opCtx)) {
+                // No need to sign cluster times for internal clients.
+                SignedLogicalTime currentTime(
+                    LogicalClock::get(opCtx)->getClusterTime(), TimeProofService::TimeProof(), 0);
+                rpc::LogicalTimeMetadata logicalTimeMetadata(currentTime);
+                logicalTimeMetadata.writeToMetadata(metadataBob);
+            } else if (auto validator = LogicalTimeValidator::get(opCtx)) {
+                auto currentTime =
+                    validator->trySignLogicalTime(LogicalClock::get(opCtx)->getClusterTime());
+                rpc::LogicalTimeMetadata logicalTimeMetadata(currentTime);
+                logicalTimeMetadata.writeToMetadata(metadataBob);
+            }
+        }
+    }
+}
+
 void appendReplyMetadata(OperationContext* opCtx,
                          const OpMsgRequest& request,
                          BSONObjBuilder* metadataBob) {
@@ -430,7 +455,9 @@ bool runCommandImpl(OperationContext* opCtx,
 
         auto result = Command::appendCommandStatus(inPlaceReplyBob, rcStatus);
         inPlaceReplyBob.doneFast();
-        replyBuilder->setMetadata(rpc::makeEmptyMetadata());
+        BSONObjBuilder metadataBob;
+        appendReplyMetadataOnError(opCtx, &metadataBob);
+        replyBuilder->setMetadata(metadataBob.done());
         return result;
     }
 
@@ -441,7 +468,9 @@ bool runCommandImpl(OperationContext* opCtx,
                 inPlaceReplyBob,
                 {ErrorCodes::InvalidOptions, "Command does not support writeConcern"});
             inPlaceReplyBob.doneFast();
-            replyBuilder->setMetadata(rpc::makeEmptyMetadata());
+            BSONObjBuilder metadataBob;
+            appendReplyMetadataOnError(opCtx, &metadataBob);
+            replyBuilder->setMetadata(metadataBob.done());
             return result;
         }
 
@@ -451,7 +480,9 @@ bool runCommandImpl(OperationContext* opCtx,
         if (!wcResult.isOK()) {
             auto result = Command::appendCommandStatus(inPlaceReplyBob, wcResult.getStatus());
             inPlaceReplyBob.doneFast();
-            replyBuilder->setMetadata(rpc::makeEmptyMetadata());
+            BSONObjBuilder metadataBob;
+            appendReplyMetadataOnError(opCtx, &metadataBob);
+            replyBuilder->setMetadata(metadataBob.done());
             return result;
         }
 
@@ -486,7 +517,9 @@ bool runCommandImpl(OperationContext* opCtx,
             inPlaceReplyBob.resetToEmpty();
             auto result = Command::appendCommandStatus(inPlaceReplyBob, linearizableReadStatus);
             inPlaceReplyBob.doneFast();
-            replyBuilder->setMetadata(rpc::makeEmptyMetadata());
+            BSONObjBuilder metadataBob;
+            appendReplyMetadataOnError(opCtx, &metadataBob);
+            replyBuilder->setMetadata(metadataBob.done());
             return result;
         }
     }
@@ -791,11 +824,14 @@ DbResponse runCommands(OperationContext* opCtx, const Message& message) {
             if (ErrorCodes::isConnectionFatalMessageParseError(ex.code()))
                 throw;
 
+            auto operationTime = LogicalClock::get(opCtx)->getClusterTime();
+            BSONObjBuilder metadataBob;
+            appendReplyMetadataOnError(opCtx, &metadataBob);
             // Otherwise, reply with the parse error. This is useful for cases where parsing fails
             // due to user-supplied input, such as the document too deep error. Since we failed
             // during parsing, we can't log anything about the command.
             LOG(1) << "assertion while parsing command: " << ex.toString();
-            _generateErrorResponse(opCtx, replyBuilder.get(), ex, rpc::makeEmptyMetadata());
+            _generateErrorResponse(opCtx, replyBuilder.get(), ex, metadataBob.obj(), operationTime);
 
             return;  // From lambda. Don't try executing if parsing failed.
         }
@@ -828,10 +864,13 @@ DbResponse runCommands(OperationContext* opCtx, const Message& message) {
 
             execCommandDatabase(opCtx, c, request, replyBuilder.get());
         } catch (const DBException& ex) {
+            BSONObjBuilder metadataBob;
+            appendReplyMetadataOnError(opCtx, &metadataBob);
+            auto operationTime = LogicalClock::get(opCtx)->getClusterTime();
             LOG(1) << "assertion while executing command '" << request.getCommandName() << "' "
                    << "on database '" << request.getDatabase() << "': " << ex.toString();
 
-            _generateErrorResponse(opCtx, replyBuilder.get(), ex, rpc::makeEmptyMetadata());
+            _generateErrorResponse(opCtx, replyBuilder.get(), ex, metadataBob.obj(), operationTime);
         }
     }();
 
diff --git a/src/mongo/s/commands/strategy.cpp b/src/mongo/s/commands/strategy.cpp
index d7aa986b930..4beb9953606 100644
--- a/src/mongo/s/commands/strategy.cpp
+++ b/src/mongo/s/commands/strategy.cpp
@@ -242,6 +242,7 @@ void runCommand(OperationContext* opCtx, const OpMsgRequest& request, BSONObjBui
     auto const commandName = request.getCommandName();
     auto const command = Command::findCommand(commandName);
     if (!command) {
+        ON_BLOCK_EXIT([opCtx, &builder] { appendRequiredFieldsToResponse(opCtx, &builder); });
         Command::appendCommandStatus(
             builder,
             {ErrorCodes::CommandNotFound, str::stream() << "no such cmd: " << commandName});
@@ -282,6 +283,7 @@ void runCommand(OperationContext* opCtx, const OpMsgRequest& request, BSONObjBui
 
             continue;
         } catch (const DBException& e) {
+            ON_BLOCK_EXIT([opCtx, &builder] { appendRequiredFieldsToResponse(opCtx, &builder); });
             builder.resetToEmpty();
             command->incrementCommandsFailed();
             Command::appendCommandStatus(builder, e.toStatus());
@@ -406,6 +408,7 @@ DbResponse Strategy::clientCommand(OperationContext* opCtx, const Message& m) {
             reply->reset();
             auto bob = reply->getInPlaceReplyBuilder(0);
             Command::appendCommandStatus(bob, ex.toStatus());
+            appendRequiredFieldsToResponse(opCtx, &bob);
 
             return;  // From lambda. Don't try executing if parsing failed.
         }
@@ -421,6 +424,7 @@ DbResponse Strategy::clientCommand(OperationContext* opCtx, const Message& m) {
             reply->reset();
             auto bob = reply->getInPlaceReplyBuilder(0);
             Command::appendCommandStatus(bob, ex.toStatus());
+            appendRequiredFieldsToResponse(opCtx, &bob);
         }
     }();