Merge pull request #38 from cgay/dev

Handle rolling logs multiple times within one second

Author: cgay

documentation/source/index.rst

@@ -85,15 +85,19 @@ log still logs to ancestor logs if they are themselves enabled.
 Errors
 ------
 
-If there is an error when parsing a :class:`<log-formatter>` format
-control string or in finding a :class:`<log>` object by name, a
-:class:`<logging-error>` will be signaled.
-
 .. class:: <logging-error>
    :open:
 
    :superclasses: :drm:`<error>`, :class:`<simple-condition>`
 
+   :description:
+
+      Errors explicitly signaled by this library are instances of
+      :class:`<logging-error>`.  Examples of when this error is signaled:
+
+      * Parsing a bad :class:`<log-formatter>` format control string.
+      * Can't find a :class:`<log>` object by name.
+      * Can't roll a log file due to file name conflicts.
 
 Log Levels
 ----------
@@ -435,7 +439,21 @@ Log Targets
    :keyword roll:
       A :drm:`<boolean>` specifying whether to roll the log file at the
       time this log target is created, if it already exists and is not
-      empty.
+      empty. The default is :drm:`#t`.
+
+   :description:
+
+      A file log target that is "rolled" when it reaches a maximum size. Rolling the log
+      file consists of renaming the current file to a name that contains the date the
+      original file was *created*.  For example, :file:`foo.log` might be renamed to
+      :file:`foo.log.20260303T185404`.  (Note that the date is in local time.)
+
+      If the log file is rolled multiple times within the same second (e.g., due to a
+      crash loop in your program) it will encounter file name conflicts. To resolve the
+      conflict the file is renamed with an additional numeric suffix concatenated to the
+      date, for example :file:`foo.log.20260303T185404.1`.  After the suffix reaches
+      ``.9`` and the file still can't be renamed without clobbering an existing file, a
+      :class:`<logging-error>` is signaled.
 
 .. class:: <stream-log-target>
    :open:

library.dylan

@@ -99,6 +99,8 @@ define module logging-impl
   use locators,
     import: { <locator>,
               <file-locator>,
+              file-locator,
+              locator-directory,
               locator-name,
               merge-locators,
               simplify-locator };

logging.dylan

@@ -706,7 +706,22 @@ define method roll-log-file
     let newloc = merge-locators(as(<file-locator>,
                                    concatenate(locator-name(oldloc), ".", date)),
                                 oldloc);
-    rename-file(oldloc, newloc);
+    // Try renaming the file up to 10 times and then give up.
+    iterate loop (attempt = 1)  // first numbered file is .1
+      block ()
+        rename-file(oldloc, newloc, if-exists: #"signal");
+        // TODO: handle <file-exists-error> once
+        // https://github.com/dylan-lang/opendylan/pull/1801 lands in an OD release.
+      exception (err :: <file-system-error>)
+        if (attempt >= 10)
+          logging-error("can't roll log file %s (10 attempts)", oldloc);
+        end;
+        newloc := file-locator(newloc.locator-directory,
+                               format-to-string("%s.%s.%d",
+                                                oldloc.locator-name, date, attempt));
+        loop(attempt + 1);
+      end;
+    end iterate;
     target.file-roll-date := current-date();
     open-target-stream(target);
   end with-lock;

tests/logging-test-suite.dylan

@@ -208,3 +208,33 @@ define test test-rolling-log-file-absolutism ()
     working-directory() := cwd;
   end block;
 end test;
+
+// Ensure that the file can roll 9 times without error and that files with numeric
+// uniquifiers are created.  (Don't check that a max of 10 rolls can occur within a
+// second because that could easily cause false failures due to the test depending on the
+// value of the clock.  I verified it manually. --cgay)
+define test test-rolling-log-file-subsecond-rolling ()
+  let dir = test-temp-directory();
+  let pathname = file-locator(dir, "foo.log");
+  let formatter = make(<log-formatter>, pattern: "%m");
+  let target = make(<rolling-file-log-target>,
+                    pathname: pathname,
+                    max-size: 1); // roll whenever something is logged
+  for (i from 1 to 10)
+    log-to-target(target, $info-level, formatter, "woof", #[]);
+  end;
+  let files = directory-contents(dir);
+  assert-true(files.size >= 9);
+  let found = 0;
+  local
+    method is-subsecond-file? (loc :: <locator>)
+      let name = loc.locator-name; // ex: "foo.log.20260303T180404.1"
+      let parts = split(name, '.');
+      if (parts.size == 4)
+        let n = string-to-integer(parts[3]);
+        assert-true(n >=1 & n <= 9, "%s is between 1 and 9 inclusive", n);
+        #t
+      end;
+    end;
+  assert-true(any?(is-subsecond-file?, files));
+end test;