Do not throw if log rotation fails.

  If log rotate fails because the file cannot be renamed
  we will keep using the same log file or in case that it
  cannot be reopen we will log to  stderr.

6 files changed, 105 insertions, 23 deletions

diff --git a/cpp/include/IceUtil/Time.h b/cpp/include/IceUtil/Time.h
index 9b29a862391..002760330b2 100644
--- a/cpp/include/IceUtil/Time.h
+++ b/cpp/include/IceUtil/Time.h
@@ -54,7 +54,7 @@ public:
 
     std::string toDateTime() const;
     std::string toDuration() const;
-    std::string toFormatString(const std::string&) const;
+    std::string toString(const std::string&) const;
 
     Time operator-() const
     {
diff --git a/cpp/src/Ice/LoggerI.cpp b/cpp/src/Ice/LoggerI.cpp
index 41809daf7b1..c35e84fee18 100644
--- a/cpp/src/Ice/LoggerI.cpp
+++ b/cpp/src/Ice/LoggerI.cpp
@@ -46,6 +46,11 @@ public:
 
 Init init;
 
+//
+// Timeout in milliseconds after which rename will be attempted
+// in case of failures renaming files. That is set to 5 minutes.
+//
+const Ice::Long retryTimeout = 5 * 60 * 1000;
 }
 
 Ice::LoggerI::LoggerI(const string& prefix, const string& file,
@@ -57,7 +62,8 @@ Ice::LoggerI::LoggerI(const string& prefix, const string& file,
 #if defined(_WIN32) && !defined(ICE_OS_WINRT)
     _consoleConverter(new IceUtil::WindowsStringConverter(GetConsoleOutputCP())),
 #endif
-    _sizeMax(sizeMax)
+    _sizeMax(sizeMax),
+    _nextRetry(0)
 {
     if(!prefix.empty())
     {
@@ -72,6 +78,11 @@ Ice::LoggerI::LoggerI(const string& prefix, const string& file,
         {
             throw InitializationException(__FILE__, __LINE__, "FileLogger: cannot open " + _file);
         }
+        
+        if(_sizeMax > 0)
+        {
+            _out.seekp(0, _out.end);
+        }
     }
 }
 
@@ -147,14 +158,13 @@ Ice::LoggerI::write(const string& message, bool indent)
     {
         if(_sizeMax > 0)
         {
-            _out.seekp(0, _out.end);
-            
             //
             // If file size + message size exceed max size we archive the log file,
             // but we do not archive empty files or truncate messages.
             //
             size_t sz = static_cast<size_t>(_out.tellp());
-            if(sz > 0 && sz + message.size() >= _sizeMax)
+            if(sz > 0 && sz + message.size() >= _sizeMax && 
+               (_nextRetry == 0 || _nextRetry <= IceUtil::Time::now().toMilliSeconds()))
             {
 
                 string basename = _file;
@@ -170,7 +180,7 @@ Ice::LoggerI::write(const string& message, bool indent)
 
                 int id = 0;
                 string archive;
-                string date = IceUtil::Time::now().toFormatString("%Y%m%d-%H%M%S");
+                string date = IceUtil::Time::now().toString("%Y%m%d-%H%M%S");
                 while(true)
                 {
                     ostringstream s;
@@ -192,17 +202,35 @@ Ice::LoggerI::write(const string& message, bool indent)
                     break;
                 }
 
-                int error = IceUtilInternal::rename(_file, archive);
-                if(error)
+                int err = IceUtilInternal::rename(_file, archive);
+                
+                _out.open(_file, fstream::out | fstream::app);
+                
+                if(err)
                 {
-                    throw InitializationException(__FILE__, __LINE__, "FileLogger: cannot rename " + _file + "\n" +
-                                                                      IceUtilInternal::lastErrorToString());
+                    _nextRetry = retryTimeout + IceUtil::Time::now().toMilliSeconds();
+                    //
+                    // We temporally set the maximum size to 0 to ensure that there isn't any rename attempts
+                    // in the nested error call.
+                    // 
+                    int sizeMax = _sizeMax;
+                    _sizeMax = 0;
+                    sync.release();
+                    error("FileLogger: cannot rename " + _file + "\n" + IceUtilInternal::lastErrorToString());
+                    sync.acquire();
+                    _sizeMax = sizeMax;
                 }
-
-                _out.open(_file, fstream::out | fstream::app);
+                else if(_nextRetry != 0)
+                {
+                    _nextRetry = 0;
+                }
+                
                 if(!_out.is_open())
                 {
-                    throw InitializationException(__FILE__, __LINE__, "FileLogger: cannot open " + _file);
+                    sync.release();
+                    error("FileLogger: cannot open " + _file + " log messages will be send to stderr");
+                    write(message, indent);
+                    return;
                 }
             }
         }
diff --git a/cpp/src/Ice/LoggerI.h b/cpp/src/Ice/LoggerI.h
index fbfb35b5a63..f6d8573df84 100644
--- a/cpp/src/Ice/LoggerI.h
+++ b/cpp/src/Ice/LoggerI.h
@@ -44,6 +44,12 @@ private:
 
     std::string _file;
     std::size_t _sizeMax;
+    
+    //
+    // In case of a log file rename failure is set to the time in milliseconds
+    // after which rename could be attempted again. Otherwise is set to zero.
+    //
+    Ice::Long _nextRetry;
 #if defined(_WIN32) && !defined(ICE_OS_WINRT)
     const IceUtil::StringConverterPtr _consoleConverter;
 #endif
diff --git a/cpp/src/IceUtil/Time.cpp b/cpp/src/IceUtil/Time.cpp
index aa6f6e944d9..a771815ddb6 100644
--- a/cpp/src/IceUtil/Time.cpp
+++ b/cpp/src/IceUtil/Time.cpp
@@ -248,7 +248,7 @@ std::string
 IceUtil::Time::toDateTime() const
 {
     std::ostringstream os;
-    os << toFormatString("%x %H:%M:%S") << ".";
+    os << toString("%x %H:%M:%S") << ".";
     os.fill('0');
     os.width(3);
     os << static_cast<long>(_usec % 1000000 / 1000);
@@ -281,7 +281,7 @@ IceUtil::Time::toDuration() const
 }
 
 std::string
-IceUtil::Time::toFormatString(const std::string& format) const
+IceUtil::Time::toString(const std::string& format) const
 {
     time_t time = static_cast<long>(_usec / 1000000);
 
diff --git a/cpp/test/Ice/logger/Client5.cpp b/cpp/test/Ice/logger/Client5.cpp
index 5948e2eed9c..b28dcf8dd94 100644
--- a/cpp/test/Ice/logger/Client5.cpp
+++ b/cpp/test/Ice/logger/Client5.cpp
@@ -135,4 +135,25 @@ main(int argc, char* argv[])
             return EXIT_FAILURE;
         }
     }
+    
+    //
+    // Run Client application configured to generate 1024 bytes, the application is configured
+    // to archive log files greater than 512 bytes, but the log directory is set to read only
+    // after the log file is created, there must not be any archived log files and the log file
+    // will contain an error indicating the failure to archive the log file
+    //
+    {
+        Ice::InitializationData id;
+        id.properties = Ice::createProperties();
+        id.properties->load("config.client");
+        id.properties->setProperty("Client.Iterations", "8");
+        id.properties->setProperty("Client.Message", message);
+        id.properties->setProperty("Ice.LogFile", "log/client5-4.log");
+        id.properties->setProperty("Ice.LogFile.SizeMax", "512");
+        Client c;
+        if(c.main(argc, argv, id) != EXIT_SUCCESS)
+        {
+            return EXIT_FAILURE;
+        }
+    }
 }
diff --git a/cpp/test/Ice/logger/run.py b/cpp/test/Ice/logger/run.py
index 1b645a5a5d2..0cc58ebc4ab 100755
--- a/cpp/test/Ice/logger/run.py
+++ b/cpp/test/Ice/logger/run.py
@@ -58,20 +58,36 @@ sys.stdout.write("testing logger file rotation... ")
 def cleanup():
     for f in glob.glob("client5-*.log"):
         os.remove(f)
+    if os.path.exists("log/client5-4.log"):
+        os.remove("log/client5-4.log")
 
 cleanup()
 
 atexit.register(cleanup)
 
-def client5():
-    p = subprocess.Popen(os.path.join(os.getcwd(), "client5"), stdout=subprocess.PIPE, stderr=subprocess.STDOUT, env=env)
-    out, err = p.communicate()
-    ret = p.poll()
-    if ret != 0:
-        print("failed! status %s " % ret)
-        sys.exit(1)
 
-client5()
+if not os.path.exists("log"):
+    os.makedirs("log")
+
+open("log/client5-4.log", 'a').close()
+
+if TestUtil.isWin32():
+    os.system("echo Y|cacls log /P %USERNAME%:R")
+else:
+    os.system("chmod -w log")
+
+
+p = subprocess.Popen(os.path.join(os.getcwd(), "client5"), stdout=subprocess.PIPE, stderr=subprocess.STDOUT, env=env)
+out, err = p.communicate()
+ret = p.poll()
+if ret != 0:
+    print("failed! status %s " % ret)
+    sys.exit(1)
+
+if TestUtil.isWin32():
+    os.system("echo Y|cacls log /P %USERNAME%:F")
+else:
+    os.system("chmod +w log")
 
 if (not os.path.isfile("client5-0.log") or
     not os.stat("client5-0.log").st_size == 512 or
@@ -112,4 +128,15 @@ for f in glob.glob("client5-3-*.log"):
         print("failed! file {0} size: {1} unexpected".format(f, os.stat(f).st_size))
         sys.exit(1)
 
+if (not os.path.isfile("log/client5-4.log") or
+    os.stat("log/client5-4.log").st_size < 1024 or
+    len(glob.glob("log/client5-4-*.log")) > 0):
+    print("failed!")
+    sys.exit(1)
+
+with open("log/client5-4.log", 'r') as f:
+    if f.read().count("error: FileLogger: cannot rename log/client5-4.log") != 1:
+        print("failed!")
+        sys.exit(1)
+
 print("ok")