From 68fc65d836fcebe9d7114cd08d614019c990b5b2 Mon Sep 17 00:00:00 2001
From: Tor Brede Vekterli <vekterli@verizonmedia.com>
Date: Tue, 26 Feb 2019 14:46:53 +0000
Subject: Log before/after bucket info for when update operation inconsistency
 is discovered

Makes it more obvious if the inconsistency is likely due to e.g. a checksum collision.
---
 .../distributor/operations/external/updateoperation.cpp  | 16 ++++++++++++++--
 .../distributor/operations/external/updateoperation.h    | 10 ++++++----
 2 files changed, 20 insertions(+), 6 deletions(-)

diff --git a/storage/src/vespa/storage/distributor/operations/external/updateoperation.cpp b/storage/src/vespa/storage/distributor/operations/external/updateoperation.cpp
index c8f28391ec0..02317ea3736 100644
--- a/storage/src/vespa/storage/distributor/operations/external/updateoperation.cpp
+++ b/storage/src/vespa/storage/distributor/operations/external/updateoperation.cpp
@@ -28,6 +28,8 @@ UpdateOperation::UpdateOperation(DistributorComponent& manager,
       _msg(msg),
       _manager(manager),
       _bucketSpace(bucketSpace),
+      _newestTimestampLocation(),
+      _infoAtSendTime(),
       _metrics(metric)
 {
 }
@@ -81,13 +83,17 @@ UpdateOperation::onStart(DistributorMessageSender& sender)
                                       "No buckets found for given document update"));
         return;
     }
+    // An UpdateOperation should only be started iff all replicas are consistent
+    // with each other, so sampling a single replica should be equal to sampling them all.
+    assert(entries[0].getBucketInfo().getNodeCount() > 0); // Empty buckets are not allowed
+    _infoAtSendTime = entries[0].getBucketInfo().getNodeRef(0).getBucketInfo();
 
     // FIXME(vekterli): this loop will happily update all replicas in the
     // bucket sub-tree, but there is nothing here at all which will fail the
     // update if we cannot satisfy a desired replication level (not even for
     // n-of-m operations).
     for (uint32_t j = 0; j < entries.size(); ++j) {
-        LOG(debug, "Found bucket %s", entries[j].toString().c_str());
+        LOG(spam, "Found bucket %s", entries[j].toString().c_str());
 
         const std::vector<uint16_t>& nodes = entries[j]->getNodes();
 
@@ -122,7 +128,7 @@ UpdateOperation::onReceive(DistributorMessageSender& sender,
 
         if (node != (uint16_t)-1) {
             if (reply.getResult().getResult() == api::ReturnCode::OK) {
-                _results.emplace_back(reply.getBucketId(), reply.getOldTimestamp(), node);
+                _results.emplace_back(reply.getBucketId(), reply.getBucketInfo(), reply.getOldTimestamp(), node);
             }
 
             if (_tracker.getReply().get()) {
@@ -155,6 +161,12 @@ UpdateOperation::onReceive(DistributorMessageSender& sender,
                         replyToSend.setNodeWithNewestTimestamp(_results[goodNode].nodeId);
                         _newestTimestampLocation.first  = _results[goodNode].bucketId;
                         _newestTimestampLocation.second = _results[goodNode].nodeId;
+
+                        LOG(warning, "Bucket info prior to update operation was: %s. After update, "
+                                     "info on node %u is %s, info on node %u is %s",
+                                     _infoAtSendTime.toString().c_str(),
+                                     _results[i].nodeId, _results[i].bucketInfo.toString().c_str(),
+                                     _results[goodNode].nodeId, _results[goodNode].bucketInfo.toString().c_str());
                         break;
                     }
                 }
diff --git a/storage/src/vespa/storage/distributor/operations/external/updateoperation.h b/storage/src/vespa/storage/distributor/operations/external/updateoperation.h
index cf432fa2305..91491485056 100644
--- a/storage/src/vespa/storage/distributor/operations/external/updateoperation.h
+++ b/storage/src/vespa/storage/distributor/operations/external/updateoperation.h
@@ -47,20 +47,22 @@ private:
     DistributorComponent& _manager;
     DistributorBucketSpace &_bucketSpace;
     std::pair<document::BucketId, uint16_t> _newestTimestampLocation;
+    api::BucketInfo _infoAtSendTime; // Should be same across all replicas
 
     bool anyStorageNodesAvailable() const;
 
-    class OldTimestamp {
+    class PreviousDocumentVersion {
     public:
-        OldTimestamp(document::BucketId b, uint64_t o, uint16_t node) :
-            bucketId(b), oldTs(o), nodeId(node) {}
+        PreviousDocumentVersion(document::BucketId b, const api::BucketInfo& info, uint64_t o, uint16_t node) :
+            bucketId(b), bucketInfo(info), oldTs(o), nodeId(node) {}
 
         document::BucketId bucketId;
+        api::BucketInfo bucketInfo;
         uint64_t oldTs;
         uint16_t nodeId;
     };
 
-    std::vector<OldTimestamp> _results;
+    std::vector<PreviousDocumentVersion> _results;
     UpdateMetricSet& _metrics;
 };
 
-- 
cgit v1.2.3