Make database failures in LeveldbValueStore more descriptive.

chrome/browser/value_store/leveldb_value_store.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "chrome/browser/value_store/leveldb_value_store.h"
 
 #include "base/file_util.h"
 #include "base/json/json_reader.h"
 #include "base/json/json_writer.h"
 #include "base/logging.h"
+#include "base/stringprintf.h"
 #include "base/sys_string_conversions.h"
 #include "content/public/browser/browser_thread.h"
 #include "third_party/leveldatabase/src/include/leveldb/iterator.h"
 #include "third_party/leveldatabase/src/include/leveldb/write_batch.h"
 
 using content::BrowserThread;
 
 namespace {
 
-// Generic error message on failure.
-const char kGenericOnFailureMessage[] = "Failure accessing database";
+const char* kInvalidJson = "Invalid JSON";
+
+ValueStore::ReadResult ReadFailure(const std::string& action,
+                                   const std::string& reason) {
+  CHECK_NE("", reason);
+  return ValueStore::MakeReadResult(base::StringPrintf(
+      "Failure to %s: %s", action.c_str(), reason.c_str()));
+}
+
+ValueStore::ReadResult ReadFailureForKey(const std::string& action,
+                                         const std::string& key,
+                                         const std::string& reason) {
+  CHECK_NE("", reason);
+  return ValueStore::MakeReadResult(base::StringPrintf(
+      "Failure to %s for key %s: %s",
+      action.c_str(), key.c_str(), reason.c_str()));
+}
+
+ValueStore::WriteResult WriteFailure(const std::string& action,
+                                     const std::string& reason) {
+  CHECK_NE("", reason);
+  return ValueStore::MakeWriteResult(base::StringPrintf(
+      "Failure to %s: %s", action.c_str(), reason.c_str()));
+}
+
+ValueStore::WriteResult WriteFailureForKey(const std::string& action,
+                                           const std::string& key,
+                                           const std::string& reason) {
+  CHECK_NE("", reason);
+  return ValueStore::MakeWriteResult(base::StringPrintf(
+      "Failure to %s for key %s: %s",
+      action.c_str(), key.c_str(), reason.c_str()));
+}
 
 // Scoped leveldb snapshot which releases the snapshot on destruction.
 class ScopedSnapshot {
  public:
   explicit ScopedSnapshot(leveldb::DB* db)
       : db_(db), snapshot_(db->GetSnapshot()) {}
 
   ~ScopedSnapshot() {
     db_->ReleaseSnapshot(snapshot_);
   }
@@ skipping 69 matching lines @@
 
 size_t LeveldbValueStore::GetBytesInUse() {
   // Let SettingsStorageQuotaEnforcer implement this.
   NOTREACHED() << "Not implemented";
   return 0;
 }
 
 ValueStore::ReadResult LeveldbValueStore::Get(
     const std::string& key) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
+
   scoped_ptr<Value> setting;
-  if (!ReadFromDb(leveldb::ReadOptions(), key, &setting)) {
-    return MakeReadResult(kGenericOnFailureMessage);
-  }
+  std::string error = ReadFromDb(leveldb::ReadOptions(), key, &setting);
+  if (!error.empty())
+    return ReadFailureForKey("get", key, error);
+
   DictionaryValue* settings = new DictionaryValue();
-  if (setting.get()) {
+  if (setting.get())
     settings->SetWithoutPathExpansion(key, setting.release());
-  }
   return MakeReadResult(settings);
 }
 
 ValueStore::ReadResult LeveldbValueStore::Get(
     const std::vector<std::string>& keys) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
+
   leveldb::ReadOptions options;
   scoped_ptr<DictionaryValue> settings(new DictionaryValue());
 
   // All interaction with the db is done on the same thread, so snapshotting
   // isn't strictly necessary.  This is just defensive.
   ScopedSnapshot snapshot(db_.get());
   options.snapshot = snapshot.get();
   for (std::vector<std::string>::const_iterator it = keys.begin();
       it != keys.end(); ++it) {
     scoped_ptr<Value> setting;
-    if (!ReadFromDb(options, *it, &setting)) {
-      return MakeReadResult(kGenericOnFailureMessage);
-    }
-    if (setting.get()) {
+    std::string error = ReadFromDb(options, *it, &setting);
+    if (!error.empty())
+      return ReadFailureForKey("get multiple keys", *it, error);
+    if (setting.get())
       settings->SetWithoutPathExpansion(*it, setting.release());
-    }
   }
 
   return MakeReadResult(settings.release());
 }
 
 ValueStore::ReadResult LeveldbValueStore::Get() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
+
   base::JSONReader json_reader;
   leveldb::ReadOptions options = leveldb::ReadOptions();
   // All interaction with the db is done on the same thread, so snapshotting
   // isn't strictly necessary.  This is just defensive.
   scoped_ptr<DictionaryValue> settings(new DictionaryValue());
 
   ScopedSnapshot snapshot(db_.get());
   options.snapshot = snapshot.get();
   scoped_ptr<leveldb::Iterator> it(db_->NewIterator(options));
   for (it->SeekToFirst(); it->Valid(); it->Next()) {
+    std::string key = it->key().ToString();
     Value* value = json_reader.ReadToValue(it->value().ToString());
-    if (value != NULL) {
-      settings->SetWithoutPathExpansion(it->key().ToString(), value);
-    } else {
+    if (value == NULL) {
       // TODO(kalman): clear the offending non-JSON value from the database.
-      LOG(ERROR) << "Invalid JSON: " << it->value().ToString();
+      return ReadFailureForKey("get all", key, kInvalidJson);
     }
+    settings->SetWithoutPathExpansion(key, value);
   }
 
-  if (!it->status().ok()) {
-    LOG(ERROR) << "DB iteration failed: " << it->status().ToString();
-    return MakeReadResult(kGenericOnFailureMessage);
+  if (it->status().IsNotFound()) {
+    NOTREACHED() << "IsNotFound() but iterating over all keys?!";
+    return MakeReadResult(settings.release());
   }
 
+  if (!it->status().ok())
+    return ReadFailure("get all", it->status().ToString());
+
   return MakeReadResult(settings.release());
 }
 
 ValueStore::WriteResult LeveldbValueStore::Set(
     WriteOptions options, const std::string& key, const Value& value) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
 
   leveldb::WriteBatch batch;
   scoped_ptr<ValueStoreChangeList> changes(new ValueStoreChangeList());
-  AddToBatch(options, key, value, &batch, changes.get());
-  return WriteToDb(&batch, changes.Pass());
+  std::string read_error =
+      AddToBatch(options, key, value, &batch, changes.get());
+  if (!read_error.empty())
+    return WriteFailureForKey("set (read)", key, read_error);
+
+  std::string write_error = WriteToDb(&batch);
+  return write_error.empty() ?
+      MakeWriteResult(changes.release()) :
+      WriteFailureForKey("set (write)", key, write_error);
 }
 
 ValueStore::WriteResult LeveldbValueStore::Set(
     WriteOptions options, const DictionaryValue& settings) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
 
   leveldb::WriteBatch batch;
   scoped_ptr<ValueStoreChangeList> changes(new ValueStoreChangeList());
 
   for (DictionaryValue::Iterator it(settings); it.HasNext(); it.Advance()) {
-    if (!AddToBatch(options, it.key(), it.value(), &batch, changes.get()))
-      return MakeWriteResult(kGenericOnFailureMessage);
+    std::string read_error =
+        AddToBatch(options, it.key(), it.value(), &batch, changes.get());
+    if (!read_error.empty())
+      return WriteFailureForKey("set multi (read)", it.key(), read_error);

[Matt Perry, 2012/09/17 19:21:35]

since this is a user-visible error, I would make it less cryptic. maybe "set
multiple values (read)". though I don't understand how this is a read operation.

[not at google - send to devlin, 2012/09/20 00:11:53]

Done.

The "read" is because it's the reading part of setting (finding the old value)
versus the writing part (writing the data). I just need something to distinguish
them.

   }
 
-  return WriteToDb(&batch, changes.Pass());
+  std::string write_error = WriteToDb(&batch);
+  return write_error.empty() ?
+      MakeWriteResult(changes.release()) :
+      WriteFailure("set multi (write)", write_error);
 }
 
 ValueStore::WriteResult LeveldbValueStore::Remove(
     const std::string& key) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
-  std::vector<std::string> keys;
-  keys.push_back(key);
-  return Remove(keys);
+  return Remove(std::vector<std::string>(1, key));
 }
 
 ValueStore::WriteResult LeveldbValueStore::Remove(
     const std::vector<std::string>& keys) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
 
   leveldb::WriteBatch batch;
   scoped_ptr<ValueStoreChangeList> changes(new ValueStoreChangeList());
 
   for (std::vector<std::string>::const_iterator it = keys.begin();
       it != keys.end(); ++it) {
     scoped_ptr<Value> old_value;
-    if (!ReadFromDb(leveldb::ReadOptions(), *it, &old_value)) {
-      return MakeWriteResult(kGenericOnFailureMessage);
-    }
+    std::string read_error =
+        ReadFromDb(leveldb::ReadOptions(), *it, &old_value);
+    if (!read_error.empty())
+      return WriteFailureForKey("remove multi (read)", *it, read_error);
 
     if (old_value.get()) {
-      changes->push_back(
-          ValueStoreChange(*it, old_value.release(), NULL));
+      changes->push_back(ValueStoreChange(*it, old_value.release(), NULL));
       batch.Delete(*it);
     }
   }
 
   leveldb::Status status = db_->Write(leveldb::WriteOptions(), &batch);
-  if (!status.ok() && !status.IsNotFound()) {
-    LOG(WARNING) << "DB batch delete failed: " << status.ToString();
-    return MakeWriteResult(kGenericOnFailureMessage);
-  }
-
-  return MakeWriteResult(changes.release());
+  return (status.ok() || status.IsNotFound()) ?
+      MakeWriteResult(changes.release()) :
+      WriteFailure("remove multi (write)", status.ToString());
 }
 
 ValueStore::WriteResult LeveldbValueStore::Clear() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
 
   leveldb::ReadOptions read_options;
   // All interaction with the db is done on the same thread, so snapshotting
   // isn't strictly necessary.  This is just defensive.
   leveldb::WriteBatch batch;
   scoped_ptr<ValueStoreChangeList> changes(new ValueStoreChangeList());
 
   ScopedSnapshot snapshot(db_.get());
   read_options.snapshot = snapshot.get();
   scoped_ptr<leveldb::Iterator> it(db_->NewIterator(read_options));
   for (it->SeekToFirst(); it->Valid(); it->Next()) {
     const std::string key = it->key().ToString();
     const std::string old_value_json = it->value().ToString();
     Value* old_value = base::JSONReader().ReadToValue(old_value_json);
-    if (old_value) {
-      changes->push_back(ValueStoreChange(key, old_value, NULL));
-    } else {
-      LOG(ERROR) << "Invalid JSON in database: " << old_value_json;
+    if (!old_value) {
+      // TODO: delete the bad JSON.
+      return WriteFailureForKey("clear (read)", key, kInvalidJson);
     }
+    changes->push_back(ValueStoreChange(key, old_value, NULL));
     batch.Delete(key);
   }
 
-  if (!it->status().ok()) {
-    LOG(WARNING) << "Clear iteration failed: " << it->status().ToString();
-    return MakeWriteResult(kGenericOnFailureMessage);
-  }
+  if (it->status().IsNotFound())
+    NOTREACHED() << "IsNotFound() but clearing?!";
+  else if (!it->status().ok())
+    return WriteFailure("clear (read)", it->status().ToString());
 
   leveldb::Status status = db_->Write(leveldb::WriteOptions(), &batch);
-  if (!status.ok() && !status.IsNotFound()) {
-    LOG(WARNING) << "Clear failed: " << status.ToString();
-    return MakeWriteResult(kGenericOnFailureMessage);
+  if (status.IsNotFound()) {
+    NOTREACHED() << "IsNotFound() but clearing?!";
+    return MakeWriteResult(changes.release());
   }
-
-  return MakeWriteResult(changes.release());
+  return status.ok() ?
+      MakeWriteResult(changes.release()) :
+      WriteFailure("clear", status.ToString());
 }
 
-bool LeveldbValueStore::ReadFromDb(
+std::string LeveldbValueStore::ReadFromDb(
     leveldb::ReadOptions options,
     const std::string& key,
     scoped_ptr<Value>* setting) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
   DCHECK(setting != NULL);
   std::string value_as_json;
   leveldb::Status s = db_->Get(options, key, &value_as_json);
 
   if (s.IsNotFound()) {
     // Despite there being no value, it was still a success.
-    return true;
+    // Check this first because ok() is false on IsNotFound.
+    return "";
   }
 
-  if (!s.ok()) {
-    LOG(ERROR) << "Error reading from database: " << s.ToString();
-    return false;
-  }
+  if (!s.ok())
+    return s.ToString();
 
   Value* value = base::JSONReader().ReadToValue(value_as_json);
   if (value == NULL) {
     // TODO(kalman): clear the offending non-JSON value from the database.
-    LOG(ERROR) << "Invalid JSON in database: " << value_as_json;
-    return false;
+    return kInvalidJson;
   }
 
   setting->reset(value);
-  return true;
+  return "";
 }
 
-bool LeveldbValueStore::AddToBatch(
+std::string LeveldbValueStore::AddToBatch(
     ValueStore::WriteOptions options,
     const std::string& key,
     const base::Value& value,
     leveldb::WriteBatch* batch,
     ValueStoreChangeList* changes) {
   scoped_ptr<Value> old_value;
   if (!(options & NO_CHECK_OLD_VALUE)) {
-    if (!ReadFromDb(leveldb::ReadOptions(), key, &old_value))
-      return false;
+    std::string error = ReadFromDb(leveldb::ReadOptions(), key, &old_value);
+    if (!error.empty())
+      return error;
   }
 
   if (!old_value.get() || !old_value->Equals(&value)) {
     if (!(options & NO_GENERATE_CHANGES)) {
       changes->push_back(
           ValueStoreChange(key, old_value.release(), value.DeepCopy()));
     }
     std::string value_as_json;
     base::JSONWriter::Write(&value, &value_as_json);
     batch->Put(key, value_as_json);
   }
 
-  return true;
+  return "";
 }
 
-ValueStore::WriteResult LeveldbValueStore::WriteToDb(
-    leveldb::WriteBatch* batch,
-    scoped_ptr<ValueStoreChangeList> changes) {
+std::string LeveldbValueStore::WriteToDb(leveldb::WriteBatch* batch) {
   leveldb::Status status = db_->Write(leveldb::WriteOptions(), batch);
-  if (!status.ok()) {
-    LOG(WARNING) << "DB batch write failed: " << status.ToString();
-    return MakeWriteResult(kGenericOnFailureMessage);
+  if (status.IsNotFound()) {
+    NOTREACHED() << "IsNotFound() but writing?!";

[not at google - send to devlin, 2012/09/17 22:17:36]

Here (and a few other places checking IsNotFound) are actual functional-ish
changes... but as the NOTREACHED implies, how writing (or clearing, or getting
from a known set) could trigger NotFound is puzzling. I even tried to go through
the leveldb source and couldn't find it.

The other reasons for failures are:
- Corruption
- NotSupported
- InvalidArgument
- IOError

which all seems like legitimate errors (perhaps I'm doing something NotSupported
somehow?)

+    return "";
   }
-
-  return MakeWriteResult(changes.release());
+  return status.ok() ? "" : status.ToString();
 }
 
 bool LeveldbValueStore::IsEmpty() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
   scoped_ptr<leveldb::Iterator> it(db_->NewIterator(leveldb::ReadOptions()));
 
   it->SeekToFirst();
   bool is_empty = !it->Valid();
   if (!it->status().ok()) {
     LOG(ERROR) << "Checking DB emptiness failed: " << it->status().ToString();
     return false;
   }
   return is_empty;
 }