You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "Andrey Turbanov (Jira)" <ji...@apache.org> on 2020/02/01 00:10:00 UTC
[jira] [Comment Edited] (LOG4J2-2769)
AtomicMoveNotSupportedException shouldn't be logged as ERROR
[ https://issues.apache.org/jira/browse/LOG4J2-2769?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17027886#comment-17027886 ]
Andrey Turbanov edited comment on LOG4J2-2769 at 2/1/20 12:09 AM:
------------------------------------------------------------------
Proposed patch:
{code}
Index: log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/action/FileRenameAction.java
===================================================================
--- log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/action/FileRenameAction.java (revision ba14e2a44edcbca73cc70b5d56af73e5b22ef238)
+++ log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/action/FileRenameAction.java (date 1580514196922)
@@ -19,6 +19,7 @@
import java.io.File;
import java.io.IOException;
import java.io.PrintWriter;
+import java.nio.file.AtomicMoveNotSupportedException;
import java.nio.file.Files;
import java.nio.file.Paths;
import java.nio.file.StandardCopyOption;
@@ -121,57 +122,64 @@
LOGGER.trace("Renamed file {} to {} with Files.move", source.getAbsolutePath(),
destination.getAbsolutePath());
return true;
+ } catch (final AtomicMoveNotSupportedException exMove) {
+ LOGGER.info("Unable to atomic move file {} to {}: {}", source.getAbsolutePath(),
+ destination.getAbsolutePath(), exMove.getMessage());
} catch (final IOException exMove) {
LOGGER.error("Unable to move file {} to {}: {} {}", source.getAbsolutePath(),
destination.getAbsolutePath(), exMove.getClass().getName(), exMove.getMessage());
- boolean result = source.renameTo(destination);
- if (!result) {
- try {
- Files.copy(Paths.get(source.getAbsolutePath()), Paths.get(destination.getAbsolutePath()),
- StandardCopyOption.REPLACE_EXISTING);
- try {
- Files.delete(Paths.get(source.getAbsolutePath()));
- result = true;
- LOGGER.trace("Renamed file {} to {} using copy and delete",
- source.getAbsolutePath(), destination.getAbsolutePath());
- } catch (final IOException exDelete) {
- LOGGER.error("Unable to delete file {}: {} {}", source.getAbsolutePath(),
- exDelete.getClass().getName(), exDelete.getMessage());
- try {
- new PrintWriter(source.getAbsolutePath()).close();
- result = true;
- LOGGER.trace("Renamed file {} to {} with copy and truncation",
- source.getAbsolutePath(), destination.getAbsolutePath());
- } catch (final IOException exOwerwrite) {
- LOGGER.error("Unable to overwrite file {}: {} {}",
- source.getAbsolutePath(), exOwerwrite.getClass().getName(),
- exOwerwrite.getMessage());
- }
- }
- } catch (final IOException exCopy) {
- LOGGER.error("Unable to copy file {} to {}: {} {}", source.getAbsolutePath(),
- destination.getAbsolutePath(), exCopy.getClass().getName(), exCopy.getMessage());
- }
- } else {
- LOGGER.trace("Renamed file {} to {} with source.renameTo",
- source.getAbsolutePath(), destination.getAbsolutePath());
- }
- return result;
- }
- } catch (final RuntimeException ex) {
- LOGGER.error("Unable to rename file {} to {}: {} {}", source.getAbsolutePath(),
- destination.getAbsolutePath(), ex.getClass().getName(), ex.getMessage());
- }
- } else {
- try {
- source.delete();
- } catch (final Exception exDelete) {
- LOGGER.error("Unable to delete empty file {}: {} {}", source.getAbsolutePath(),
- exDelete.getClass().getName(), exDelete.getMessage());
- }
- }
-
- return false;
+ }
+ return nonAtomicMove(source, destination);
+ } catch (final RuntimeException ex) {
+ LOGGER.error("Unable to rename file {} to {}: {} {}", source.getAbsolutePath(),
+ destination.getAbsolutePath(), ex.getClass().getName(), ex.getMessage());
+ }
+ } else {
+ try {
+ source.delete();
+ } catch (final Exception exDelete) {
+ LOGGER.error("Unable to delete empty file {}: {} {}", source.getAbsolutePath(),
+ exDelete.getClass().getName(), exDelete.getMessage());
+ }
+ }
+
+ return false;
+ }
+
+ private static boolean nonAtomicMove(File source, File destination) {
+ boolean result = source.renameTo(destination);
+ if (!result) {
+ try {
+ Files.copy(Paths.get(source.getAbsolutePath()), Paths.get(destination.getAbsolutePath()),
+ StandardCopyOption.REPLACE_EXISTING);
+ try {
+ Files.delete(Paths.get(source.getAbsolutePath()));
+ result = true;
+ LOGGER.trace("Renamed file {} to {} using copy and delete",
+ source.getAbsolutePath(), destination.getAbsolutePath());
+ } catch (final IOException exDelete) {
+ LOGGER.error("Unable to delete file {}: {} {}", source.getAbsolutePath(),
+ exDelete.getClass().getName(), exDelete.getMessage());
+ try {
+ new PrintWriter(source.getAbsolutePath()).close();
+ result = true;
+ LOGGER.trace("Renamed file {} to {} with copy and truncation",
+ source.getAbsolutePath(), destination.getAbsolutePath());
+ } catch (final IOException exOwerwrite) {
+ LOGGER.error("Unable to overwrite file {}: {} {}",
+ source.getAbsolutePath(), exOwerwrite.getClass().getName(),
+ exOwerwrite.getMessage());
+ }
+ }
+ } catch (final IOException exCopy) {
+ LOGGER.error("Unable to copy file {} to {}: {} {}", source.getAbsolutePath(),
+ destination.getAbsolutePath(), exCopy.getClass().getName(), exCopy.getMessage());
+ }
+ } else {
+ LOGGER.trace("Renamed file {} to {} with source.renameTo",
+ source.getAbsolutePath(), destination.getAbsolutePath());
+ }
+ return result;
}
@Override
{code}
I've extracted exception case to separate method {{nonAtomicMove}} to make JIT compilation of fast-path easier.
was (Author: turbanoff):
Proposed patch:
{code}
Index: log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/action/FileRenameAction.java
===================================================================
--- log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/action/FileRenameAction.java (revision ba14e2a44edcbca73cc70b5d56af73e5b22ef238)
+++ log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/action/FileRenameAction.java (date 1580514196922)
@@ -19,6 +19,7 @@
import java.io.File;
import java.io.IOException;
import java.io.PrintWriter;
+import java.nio.file.AtomicMoveNotSupportedException;
import java.nio.file.Files;
import java.nio.file.Paths;
import java.nio.file.StandardCopyOption;
@@ -121,57 +122,64 @@
LOGGER.trace("Renamed file {} to {} with Files.move", source.getAbsolutePath(),
destination.getAbsolutePath());
return true;
+ } catch (final AtomicMoveNotSupportedException exMove) {
+ LOGGER.info("Unable to atomic move file {} to {}: {}", source.getAbsolutePath(),
+ destination.getAbsolutePath(), exMove.getMessage());
} catch (final IOException exMove) {
LOGGER.error("Unable to move file {} to {}: {} {}", source.getAbsolutePath(),
destination.getAbsolutePath(), exMove.getClass().getName(), exMove.getMessage());
- boolean result = source.renameTo(destination);
- if (!result) {
- try {
- Files.copy(Paths.get(source.getAbsolutePath()), Paths.get(destination.getAbsolutePath()),
- StandardCopyOption.REPLACE_EXISTING);
- try {
- Files.delete(Paths.get(source.getAbsolutePath()));
- result = true;
- LOGGER.trace("Renamed file {} to {} using copy and delete",
- source.getAbsolutePath(), destination.getAbsolutePath());
- } catch (final IOException exDelete) {
- LOGGER.error("Unable to delete file {}: {} {}", source.getAbsolutePath(),
- exDelete.getClass().getName(), exDelete.getMessage());
- try {
- new PrintWriter(source.getAbsolutePath()).close();
- result = true;
- LOGGER.trace("Renamed file {} to {} with copy and truncation",
- source.getAbsolutePath(), destination.getAbsolutePath());
- } catch (final IOException exOwerwrite) {
- LOGGER.error("Unable to overwrite file {}: {} {}",
- source.getAbsolutePath(), exOwerwrite.getClass().getName(),
- exOwerwrite.getMessage());
- }
- }
- } catch (final IOException exCopy) {
- LOGGER.error("Unable to copy file {} to {}: {} {}", source.getAbsolutePath(),
- destination.getAbsolutePath(), exCopy.getClass().getName(), exCopy.getMessage());
- }
- } else {
- LOGGER.trace("Renamed file {} to {} with source.renameTo",
- source.getAbsolutePath(), destination.getAbsolutePath());
- }
- return result;
- }
- } catch (final RuntimeException ex) {
- LOGGER.error("Unable to rename file {} to {}: {} {}", source.getAbsolutePath(),
- destination.getAbsolutePath(), ex.getClass().getName(), ex.getMessage());
- }
- } else {
- try {
- source.delete();
- } catch (final Exception exDelete) {
- LOGGER.error("Unable to delete empty file {}: {} {}", source.getAbsolutePath(),
- exDelete.getClass().getName(), exDelete.getMessage());
- }
- }
-
- return false;
+ }
+ return nonAtomicMove(source, destination);
+ } catch (final RuntimeException ex) {
+ LOGGER.error("Unable to rename file {} to {}: {} {}", source.getAbsolutePath(),
+ destination.getAbsolutePath(), ex.getClass().getName(), ex.getMessage());
+ }
+ } else {
+ try {
+ source.delete();
+ } catch (final Exception exDelete) {
+ LOGGER.error("Unable to delete empty file {}: {} {}", source.getAbsolutePath(),
+ exDelete.getClass().getName(), exDelete.getMessage());
+ }
+ }
+
+ return false;
+ }
+
+ private static boolean nonAtomicMove(File source, File destination) {
+ boolean result = source.renameTo(destination);
+ if (!result) {
+ try {
+ Files.copy(Paths.get(source.getAbsolutePath()), Paths.get(destination.getAbsolutePath()),
+ StandardCopyOption.REPLACE_EXISTING);
+ try {
+ Files.delete(Paths.get(source.getAbsolutePath()));
+ result = true;
+ LOGGER.trace("Renamed file {} to {} using copy and delete",
+ source.getAbsolutePath(), destination.getAbsolutePath());
+ } catch (final IOException exDelete) {
+ LOGGER.error("Unable to delete file {}: {} {}", source.getAbsolutePath(),
+ exDelete.getClass().getName(), exDelete.getMessage());
+ try {
+ new PrintWriter(source.getAbsolutePath()).close();
+ result = true;
+ LOGGER.trace("Renamed file {} to {} with copy and truncation",
+ source.getAbsolutePath(), destination.getAbsolutePath());
+ } catch (final IOException exOwerwrite) {
+ LOGGER.error("Unable to overwrite file {}: {} {}",
+ source.getAbsolutePath(), exOwerwrite.getClass().getName(),
+ exOwerwrite.getMessage());
+ }
+ }
+ } catch (final IOException exCopy) {
+ LOGGER.error("Unable to copy file {} to {}: {} {}", source.getAbsolutePath(),
+ destination.getAbsolutePath(), exCopy.getClass().getName(), exCopy.getMessage());
+ }
+ } else {
+ LOGGER.trace("Renamed file {} to {} with source.renameTo",
+ source.getAbsolutePath(), destination.getAbsolutePath());
+ }
+ return result;
}
@Override
{code}
I've extracted exception case to separate method {{nonAtomicMove}} to make JIT compilation of common-case easier.
> AtomicMoveNotSupportedException shouldn't be logged as ERROR
> ------------------------------------------------------------
>
> Key: LOG4J2-2769
> URL: https://issues.apache.org/jira/browse/LOG4J2-2769
> Project: Log4j 2
> Issue Type: Improvement
> Components: Appenders
> Affects Versions: 2.13.0
> Reporter: Andrey Turbanov
> Priority: Minor
> Fix For: 2.13.1
>
>
> When RollingFileAppender moves file to another folder, it tries to use [ATOMIC_MOVE|https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/nio/file/StandardCopyOption.html#ATOMIC_MOVE] option as most strong one approach.
> In many common production cases this approach *always* fails, and {{RollingFileAppender}} fallbacks (which is good) to use [File.renameTo|https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/io/File.html#renameTo(java.io.File)] method. One of such common case - using network filesystem for _cold_ logs (E.g. CIFS).
> When atomic move fails it prints error to the log. Something like this:
> {code}
> ERROR Unable to move file /opt/log/console.60465.pp1.log to /opt/case/20200130/console.60465.pp1.20200130_193421.log: java.nio.file.AtomicMoveNotSupportedException /opt/log/console.60465.pp1.log -> /opt/case/20200130/console.60465.pp1.20200130_193421.log: Invalid cross-device link
> {code}
> Such logs are very distracting and can lead to unnecessary monitoring alerts.
> I suggest to lower logging level for such case to INFO or WARN. As it's *expected* scenario.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)