fix for log UI Commands

Save documentID to the log, and rewrote reporting script to
reorder the file. (because looks like some cases more kit processes
wrote into the permanent file at the same time, and their log mixed)

fixed a configuration path problem
fixed a click merge problem

Signed-off-by: Attila Szűcs <attila.szucs@collabora.com>
Change-Id: Ibf1281b560d94c7ea9a97614dd1648aaa10f00f7

common/Log.cpp

@@ -697,7 +697,6 @@ namespace Log
                 channelUILog->setProperty(pair.first, pair.second);
             }
 
-            channelUILog = static_cast<Poco::Channel*>(new Poco::FileChannel("/tmp/coolwsd-ui-cmd.log"));
             channelUILog->open();
             try
             {

kit/ChildSession.cpp

@@ -3847,7 +3847,8 @@ void LogUiCommands::logLine(LogUiCommandsLine &line, bool isUndoChange)
     // log command
     double timeDiffStart = std::chrono::duration<double>(line._timeStart - _session->_docManager->getLogUiCmd().getKitStartTimeSec()).count();
     std::stringstream strToLog;
-    strToLog << "time=" << std::fixed << std::setprecision(3) << timeDiffStart;
+    strToLog << "kit=" << _session->_docManager->getDocId();
+    strToLog << " time=" << std::fixed << std::setprecision(3) << timeDiffStart;
     if (Log::isLogUITimeEnd())
     {
         double timeDiffEnd = std::chrono::duration<double>(line._timeEnd - line._timeStart).count();
@@ -3947,6 +3948,7 @@ LogUiCommands::~LogUiCommands()
 
                     // If it is a buttonup and we have a saved buttondown, than exchange it to click
                     if (actSubCmd == "buttonup" && lineCount > 0
+                        && _session->_lastUiCmdLinesLogged[lineCount - 1]._cmd == "mouse"
                         && _session->_lastUiCmdLinesLogged[lineCount - 1]._subCmd == "buttondown")
                     {
                         if (lineCount == 1)
@@ -3989,7 +3991,7 @@ LogUiCommands::~LogUiCommands()
                 else
                     undoChg = -1;
             }
-            if (commandHandled && undoChg != 0)
+            if (commandHandled)
             {
                 // Now, possible only if a buttonup become click
                 line0._undoChange += undoChg;
@@ -4003,7 +4005,7 @@ LogUiCommands::~LogUiCommands()
             if (lineCount >= 2)
             {
                 // Possible only if, the stored commands are: mouse click + mouse button down
-                // but it the actual is not a mouse up .. that was handled before
+                // but the actual is not a mouse up .. that was handled before
                 // We have to log the 1. line, and copy the 2. to the first.
                 logLine(line1);
                 line0 = line1;
@@ -4020,20 +4022,28 @@ LogUiCommands::~LogUiCommands()
                     line0._undoChange += undoChg;
                     return;
                 }
+                else if (line0._cmd == "mouse" && line0._subCmd == "click"
+                         && actCmd == "mouse" && actSubCmd == "buttondown")
+                {
+                    // mouse button down after a click, may become 2x click later, do not log it yet
+                    // Nothing to do here now. (lineCount == 1)
+                }
                 else
                 {
                     // We can not merge. We log the last stored command, and continue to store the actual command
                     logLine(line0);
+                    lineCount = 0;
                 }
             }
             // Store new command
-            line0._cmd = actCmd;
-            line0._subCmd = actSubCmd;
-            line0._repeat = 1;
-            line0._undoChange = undoChg;
-            line0._timeStart = actTime;
-            line0._timeEnd = actTime;
-            lineCount = 1;
+            LogUiCommandsLine& lineAct = _session->_lastUiCmdLinesLogged[lineCount];
+            lineAct._cmd = actCmd;
+            lineAct._subCmd = actSubCmd;
+            lineAct._repeat = 1;
+            lineAct._undoChange = undoChg;
+            lineAct._timeStart = actTime;
+            lineAct._timeEnd = actTime;
+            lineCount++;
 
             if (!Log::isLogUIMerged())
             {

kit/Kit.cpp

@@ -775,7 +775,7 @@ Document::Document(const std::shared_ptr<lok::Office>& loKit, const std::string&
     // Open file for UI Logging
     if (Log::isLogUIEnabled())
     {
-        logUiCmd.createTmpFile();
+        logUiCmd.createTmpFile(_docId);
     }
 }
 

kit/Kit.hpp

@@ -248,6 +248,7 @@ class Document final : public std::enable_shared_from_this<Document>, private Ti
     }
 
     unsigned getMobileAppDocId() const { return _mobileAppDocId; }
+    const std::string getDocId() const { return _docId; }
 
     /// See if we should clear out our memory
     void trimIfInactive();

kit/LogUI.cpp

@@ -22,7 +22,7 @@ void LogUiCmd::logUiCmdLine(int userId, const std::string& line)
 
 void LogUiCmd::saveLogFile()
 {
-    std::string timeLog = "log-start-time: " + _kitStartTimeStr + " user-count:" + std::to_string(_usersLogged.size());
+    std::string timeLog = "log-start-time: " + _kitStartTimeStr + " kit=" + _docId + " user-count:" + std::to_string(_usersLogged.size());
     Log::logUI(Log::WRN, timeLog);
     _fileStreamUICommands.seekg(0, std::ios::beg);
     std::string line;
@@ -34,15 +34,17 @@ void LogUiCmd::saveLogFile()
     _fileStreamUICommands.close();
     timeLog = "log-end-time: ";
     timeLog.append(Util::getTimeNow("%Y-%m-%d %T"));
+    timeLog += " kit=" + _docId;
     Log::logUI(Log::WRN, timeLog);
 }
 
-void LogUiCmd::createTmpFile()
+void LogUiCmd::createTmpFile(std::string docId)
 {
     const std::string tempFile = "/tmp/kit-ui-cmd.log";
     _fileStreamUICommands.open(tempFile, std::fstream::in | std::fstream::out | std::fstream::trunc);
     _kitStartTimeSec = std::chrono::steady_clock::now();
     _kitStartTimeStr = Util::getTimeNow("%Y-%m-%d %T");
+    _docId = docId;
 }
 
 std::chrono::steady_clock::time_point LogUiCmd::getKitStartTimeSec()

kit/LogUI.hpp

@@ -19,7 +19,7 @@
 class LogUiCmd
 {
 public:
-    void createTmpFile();
+    void createTmpFile(std::string docId);
     void logUiCmdLine(int userId, const std::string& line);
     void saveLogFile();
     std::chrono::steady_clock::time_point getKitStartTimeSec();
@@ -29,4 +29,5 @@ class LogUiCmd
     std::chrono::steady_clock::time_point _kitStartTimeSec;
     std::string _kitStartTimeStr;
     std::set<int> _usersLogged;
+    std::string _docId;
 };

scripts/undoStatistics.py

@@ -37,6 +37,51 @@ class User:
     undoChgStack = []       # list of commands that made changes
     lastCmd = ""
 
+class FileLine:
+    def __init__(self, kit, lineString):
+        self.kit = kit
+        self.lineString = lineString
+    kit = 0
+    lineString = ""
+
+def reorderLogFile(oldFilename):
+    newFileName = oldFilename + ".reordered"
+    f = open(oldFilename, 'r')
+
+    fileLines = []
+    kitStartLine = {}
+    kitEndLine = {}
+    i = 0
+
+    for line in f:
+        numbKit = line.find("kit=")
+        if numbKit >= 0:
+            endOfKit = line[numbKit:].find(" ")
+            if endOfKit >= 0:
+                endOfKit += numbKit
+                kit = int(line[numbKit+4:endOfKit])
+            else:
+                kit = int(line[numbKit+4:])
+
+            fileLines.append(FileLine(kit,line))
+
+            if kit not in kitStartLine:
+                kitStartLine[kit] = i
+            kitEndLine[kit] = i
+            i += 1
+
+    fOut = open(newFileName, "w")
+
+    for kit in kitEndLine.keys():
+        for i in range(kitStartLine[kit], kitEndLine[kit]+1):
+            if fileLines[i].kit == kit:
+                fOut.write(fileLines[i].lineString)
+
+    fOut.close()
+    f.close()
+
+    return newFileName
+
 if __name__ == "__main__":
 
     if len(sys.argv) != 2:
@@ -49,8 +94,11 @@ class User:
     undoedCommands = {}
     totalUndoedCommands = {}
 
+    # Check if the file has kit order problem, and fix it
+    newFileName = reorderLogFile(sys.argv[1])
+
     # Process all Document related, and undo related calculations
-    f = open(sys.argv[1], 'r')
+    f = open(newFileName, 'r')
     for line in f:
         if line.startswith("log-start-time:"):
             pass
@@ -108,7 +156,7 @@ class User:
         totalUndoedCommands[cmd] = 0
 
     actIndex=-1
-    f = open(sys.argv[1], 'r')
+    f = open(newFileName, 'r')
     for line in f:
         if line.startswith("time="):
             numbrep = line.find("rep=")