From db13014e00358303f577518c96e29e23e544c1a8 Mon Sep 17 00:00:00 2001
From: Pranav Kant <pranavk@collabora.co.uk>
Date: Sat, 10 Jun 2017 20:15:00 +0530
Subject: [PATCH] Update modifiedTime for local files unconditionally

Also teach logger to print timestamp object.

Change-Id: Ia13836814c195cef92f5dafd8245c9958600876d
---
 common/Log.hpp         | 14 ++++++++++++++
 wsd/DocumentBroker.cpp | 18 +++++++++---------
 wsd/Storage.cpp        | 10 +++++++---
 3 files changed, 30 insertions(+), 12 deletions(-)

diff --git a/common/Log.hpp b/common/Log.hpp
index 21de30f653..0be4983f55 100644
--- a/common/Log.hpp
+++ b/common/Log.hpp
@@ -17,6 +17,9 @@
 #include <sstream>
 #include <string>
 
+#include <Poco/DateTime.h>
+#include <Poco/DateTimeFormat.h>
+#include <Poco/DateTimeFormatter.h>
 #include <Poco/Logger.h>
 
 namespace Log
@@ -170,6 +173,17 @@ namespace Log
         return lhs;
     }
 
+    inline StreamLogger& operator<<(StreamLogger& lhs, const Poco::Timestamp& rhs)
+    {
+        if (lhs.enabled())
+        {
+            lhs._stream <<  Poco::DateTimeFormatter::format(Poco::DateTime(rhs),
+                                                            Poco::DateTimeFormat::ISO8601_FRAC_FORMAT);
+        }
+
+        return lhs;
+    }
+
     inline void operator<<(StreamLogger& lhs, const _end_marker&)
     {
         (void)end;
diff --git a/wsd/DocumentBroker.cpp b/wsd/DocumentBroker.cpp
index d4ac586a99..fd04998ae6 100644
--- a/wsd/DocumentBroker.cpp
+++ b/wsd/DocumentBroker.cpp
@@ -510,21 +510,21 @@ bool DocumentBroker::load(const std::shared_ptr<ClientSession>& session, const s
     if (firstInstance)
     {
         _documentLastModifiedTime = fileInfo._modifiedTime;
-        LOG_DBG("Document timestamp: " << Poco::DateTimeFormatter::format(Poco::DateTime(_documentLastModifiedTime),
-                                                                          Poco::DateTimeFormat::ISO8601_FORMAT));
+        Log::debug() << "Document timestamp: " << _documentLastModifiedTime << Log::end;
     }
     else
     {
         // Check if document has been modified by some external action
-        LOG_TRC("Document modified time: " <<
-                Poco::DateTimeFormatter::format(Poco::DateTime(fileInfo._modifiedTime),
-                                                Poco::DateTimeFormat::ISO8601_FORMAT));
+        Log::trace() << "Document modified time: " << fileInfo._modifiedTime << Log::end;
         static const Poco::Timestamp Zero(Poco::Timestamp::fromEpochTime(0));
         if (_documentLastModifiedTime != Zero &&
             fileInfo._modifiedTime != Zero &&
             _documentLastModifiedTime != fileInfo._modifiedTime)
         {
-            LOG_WRN("Document [" << _docKey << "] has been modified behind our back. Informing all clients.");
+            Log::trace() << "Document " << _docKey << "] has been modified behind our back. Informing all clients."
+                         << "Expected: " << _documentLastModifiedTime
+                         << "Actual: " << fileInfo._modifiedTime << Log::end;
+
             _documentChangedInStorage = true;
             const std::string errorMsg = "error: cmd=storage kind=documentconflict";
             session->sendTextFrame(errorMsg);
@@ -658,9 +658,9 @@ bool DocumentBroker::saveToStorageInternal(const std::string& sessionId,
         // After a successful save, we are sure that document in the storage is same as ours
         _documentChangedInStorage = false;
 
-        LOG_DBG("Saved docKey [" << _docKey << "] to URI [" << uri << "] and updated tile cache. Document modified timestamp: " <<
-                Poco::DateTimeFormatter::format(Poco::DateTime(_documentLastModifiedTime),
-                                                               Poco::DateTimeFormat::ISO8601_FORMAT));
+        Log::debug() << "Saved docKey [" << _docKey << "] to URI [" << uri
+                     << "] and updated tile cache. Document modified timestamp: "
+                     << _documentLastModifiedTime << Log::end;
         return true;
     }
     else if (storageSaveResult == StorageBase::SaveResult::DISKFULL)
diff --git a/wsd/Storage.cpp b/wsd/Storage.cpp
index af31674e35..bc20544647 100644
--- a/wsd/Storage.cpp
+++ b/wsd/Storage.cpp
@@ -286,16 +286,20 @@ StorageBase::SaveResult LocalStorage::saveLocalFileToStorage(const std::string&
 {
     try
     {
+        LOG_TRC("Saving local file to local file storage " << _isCopy << " for " << _jailedFilePath);
         // Copy the file back.
         if (_isCopy && Poco::File(_jailedFilePath).exists())
         {
             LOG_INF("Copying " << _jailedFilePath << " to " << _uri.getPath());
             Poco::File(_jailedFilePath).copyTo(_uri.getPath());
 
-            // update its fileinfo object. This is used later to check if someone else changed the
-            // document while we are/were editing it
-            _fileInfo._modifiedTime = Poco::File(_uri.getPath()).getLastModified();
+
         }
+
+        // update its fileinfo object. This is used later to check if someone else changed the
+        // document while we are/were editing it
+        _fileInfo._modifiedTime = Poco::File(_uri.getPath()).getLastModified();
+        Log::trace() << "New FileInfo modified time in storage " << _fileInfo._modifiedTime << Log::end;
     }
     catch (const Poco::Exception& exc)
     {