wildfly 23.0.2 server.log not rotating

[Keith Brewer]

We're running Wildfly 23.0.2, and for quite some time now server.log hasn't been rotating. We've added a little bit of extra stuff to the logging section of standalone.xml, but believe we've been careful not to interfere with the server.log's config, with the periodic-rotating-file-handler. There's no error message in the terminal and no error message in the log.

However, we do have a Log4j2 configuration embedded in our application, and I'm wondering if that could somehow be interfering with the rotator. This is happening across all of our deployments, so it's not just a case of "is the log open in notepad?". Right now I'm thinking our Log4j2 management is messing it up somehow. Unless other thoughts can be offered as to what could possibly cause the rotation to either not run, or fail while running but not report the issue. Actual logging is fine, it just stopped rotating.

[James Perkins]

Does your log4j configuration also write to the server.log? If so, that really shouldn't be done. If not, could you post your logging section of your configuration for both WildFly and log4j?

[Keith Brewer]

Sorry in advance for the big info dump and lack of formatting, there doesn't seem to be code tags. To preface this with a bit of confusion, we've taken over "server.log" for dedicated app logging, and renamed the server.log file reference in standalone.xml to "wildfly.log".

So, a bit of explanation. We were previously solely using the mostly default logging configuration in standalone.xml. Recently there was a push to update and tweak the logging configurations in preparation for involving ES / Kibana in our logging. To that end we created a Log4J2 configuration to mark up our logs a bit for easy tagging and searching. We wanted to have a clean separation of Wildfly handling its own logging needs for itself, and the logging for our app would be dedicated to a separate file as well. Wildfly will use wildfly.log, and we will commandeer server.log.

However, we currently have a temporary need for our app's dedicated logging to go to wildfly.log too, not just server.log (this should be removed at some point). So we have a bit of a complicated extra configuration. In Log4J, we send our app logging to both server.log, and to stdout. Now, in standalone.xml, we capture that stdout output and have a handler to send it to wildfly.log. They previously had a duplicate "periodic-rotating-file-handler" block below the first one, with the same path and filename, but I believe this is what was causing rotation to fail with a "file in use" exception. I see that there are about 6 different file handler types for logging, so I picked "<file-handler>" to update that second periodic rotator block, since it seemed to fit (although I can't find a more in-depth description of each file handler type). Now it's not attempting rotation at all. I'm no expert in the standalone.xml configuration, but from what I've read, the wildfly.log file defined in the one and only periodic-rotating-file-handler block should be rotating as specified. I'm 100% open to the configuration being the problem, but I'm wondering if the config is actually ok and it's something in our log4j2 java config and setup code that's breaking the rotation somehow.

Here is the logging block for standalone.xml:

<subsystem xmlns="urn:jboss:domain:logging:8.0">
            <console-handler name="SIMPLE" autoflush="true">
                <level name="INFO"/>
                <formatter>
                    <named-formatter name="SIMPLE-PATTERN"/>
                </formatter>
            </console-handler>
            <console-handler name="CONSOLE" autoflush="true">
                <level name="INFO"/>
                <formatter>
                    <named-formatter name="COLOR-PATTERN"/>
                </formatter>
            </console-handler>
            <periodic-rotating-file-handler name="FILE" autoflush="true">
                <formatter>
                    <named-formatter name="PATTERN"/>
                </formatter>
                <file relative-to="jboss.server.log.dir" path="wildfly.log"/>
                <suffix value=".yyyy-MM-dd"/>
                <append value="true"/>
            </periodic-rotating-file-handler>
            <file-handler name="SIMPLE-FILE" autoflush="true">
                <formatter>
                    <named-formatter name="SIMPLE-FILE-PATTERN"/>
                </formatter>
                <file relative-to="jboss.server.log.dir" path="wildfly.log"/>
                <append value="true"/>
            </file-handler>
            <logger category="com.arjuna">
                <level name="WARN"/>
            </logger>
            <logger category="io.jaegertracing.Configuration">
                <level name="WARN"/>
            </logger>
            <logger category="org.jboss.as.config">
                <level name="DEBUG"/>
            </logger>
            <logger category="sun.rmi">
                <level name="WARN"/>
            </logger>
            <logger category="org.hibernate.orm.deprecation">
                <level name="OFF"/>
            </logger>
            <logger category="org.jboss.as.server.deployment">
                <level name="ERROR"/>
            </logger>
            <logger category="com.mystuff.api.wicket.util">
                <level name="ERROR"/>
            </logger>
            <logger category="StatusLogger">
                <level name="ERROR"/>
            </logger>
            <logger category="stdout" use-parent-handlers="false">
                <level name ="INFO"/>
                <handlers>
                  <handler name="SIMPLE"/>
                  <handler name="SIMPLE-FILE"/>
                </handlers>
            </logger>
            <logger category="stderr" use-parent-handlers="false">
                <level name ="INFO"/>
                <handlers>
                  <handler name="SIMPLE"/>
                  <handler name="SIMPLE-FILE"/>
                </handlers>
            </logger>

            <root-logger>
                <level name="INFO"/>
                <handlers>
                    <handler name="CONSOLE"/>
                    <handler name="FILE"/>
                </handlers>
            </root-logger>
            <formatter name="PATTERN">
                <pattern-formatter pattern="/WILDFLY   / %d{YYYY-MM-dd HH:mm:ss.SSS} [%-20.20t] [%-5.5p] [%-36.36c] - %s%e%n"/>
            </formatter>
            <formatter name="COLOR-PATTERN">
                <pattern-formatter pattern="%K{level}/WILDFLY   / %d{YYYY-MM-dd HH:mm:ss.SSS} [%-20.20t] %-5.5p [%-36.36c] - %s%e%n"/>
            </formatter>
            <formatter name="SIMPLE-PATTERN">
                <pattern-formatter pattern="%K{level}%s%e%n"/>
            </formatter>
            <formatter name="SIMPLE-FILE-PATTERN">
                <pattern-formatter pattern="%s%e%n"/>
            </formatter>
        </subsystem>

======================

======================

======================

======================

Here is the log4j2 configuration:

<Configuration status="ERROR">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="/%-10.10X{myApp}/ %d{YYYY-MM-dd HH:mm:ss.SSS} [%-20.20t] %-5level %-36.36logger{1.} - %msg                ^%X^\n"/>
        </Console>
        <RollingFile name="roll" fileName="${env:JBOSS_HOME}/standalone/log/server.log" filePattern="${env:JBOSS_HOME}/standalone/log/server.log.%d{yyyy-MM-dd}" ignoreExceptions="false">
            <PatternLayout pattern="/%-10.10X{myApp}/ %d{YYYY-MM-dd HH:mm:ss.SSS} [%-20.20t] %-5level %-36.36logger{1.} - %msg                ^%X^%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
            </Policies>
            <DefaultRolloverStrategy max="3">
                <Delete basePath="${env:JBOSS_HOME}/standalone/log/" maxDepth="1">
                    <IfFileName glob="*/server.log*">
                        <IfLastModified age="P4D"/>
                    </IfFileName>
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
    </Appenders>
    <Loggers>
        <Logger name="com.mystuff.api.wicket.util" level="ERROR">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="roll"/>
        </Logger>
        <Logger name="org.hibernate.orm.deprecation" level="OFF">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="roll"/>
        </Logger>
        <Logger name="com.arjuna" level="WARN">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="roll"/>
        </Logger>
        <Logger name="io.jaegertracing.Configuration" level="WARN">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="roll"/>
        </Logger>
        <Logger name="sun.rmi" level="WARN">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="roll"/>
        </Logger>
        <Logger name="StatusLogger" level="ERROR">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="roll"/>
        </Logger>
        <Root level="INFO">
            <AppenderRef ref="Console"/>
            <AppenderRef ref="roll"/>
        </Root>
    </Loggers>
</Configuration>

[James Perkins]

Hello. Thank for the detailed response. The configuration issue I see is 

            <periodic-rotating-file-handler name="FILE" autoflush="true">
                <formatter>
                    <named-formatter name="PATTERN"/>
                </formatter>
                <file relative-to="jboss.server.log.dir" path="wildfly.log"/>
                <suffix value=".yyyy-MM-dd"/>
                <append value="true"/>
            </periodic-rotating-file-handler>
            <file-handler name="SIMPLE-FILE" autoflush="true">
                <formatter>
                    <named-formatter name="SIMPLE-FILE-PATTERN"/>
                </formatter>
                <file relative-to="jboss.server.log.dir" path="wildfly.log"/>
                <append value="true"/>
            </file-handler>

You've got two different handlers writing to the same file. Doing something like this you may end up with jumbled logs if they are being written at the same time. There is likely also issues on Windows given the SIMPLE-FILE handler will have a lock on the file so the FILE handler won't be able to rotated.

You by no means need to give details, but is there something missing in the logging configuration for WildFly that would not allow it to be consumed by your Kibana instance?

[Keith Brewer]

Oh I don't really know anything about the kibana bit. All I know about kibana is that you can log in to it and search for stuff, and I guess it's a frontend for ElasticSearch, or something? I'm not knowledgeable in that area.

Honestly this whole problem would go away, but it's because of QA, lol. In the QA environment, they like to run wildfly through standalone.bat in a CMD window and watch the output there (production runs it as a service). It's mostly because the output can be watched live, as it seems like there aren't any good tail-ing utilities on windows to accomplish the same thing through the log file, although it's been many years since anyone tried looking. I'm sure there has to be something out there that can do the equivalent of tail on linux, or have the same effect as watching standalone.bat's cmd window. Also, it seems like there are, very rarely, some things that go to the console window directly but not the log file (one part of the issue with the file rotation had this happen, it printed a single error line directly to the console, and it wasn't in the log file).

If it wasn't for this, we wouldn't need the stdout appender in log4j2 and I think everything would happen just swimmingly since it would be cleanly separated. But given how Windows works, it makes complete sense that we'd have this issue (probably not a problem to be doing this on linux). It sounds like we may simply be up a creek on the issue. Thanks for the quick responses.

[James Perkins]

Ah, got it. Not a problem at all. I'd definitely change the SIMPLE-FILE to use a new file name, something like wildfly-simple.log or something. You really don't want two handlers from any log manager writing to the same file. Yomu ighe tnd up with lmessog ages like this. lol

[Keith Brewer]

Ok, so, revisiting this. I removed the <file-handler> just in case it might conflict with the <periodic-rotating-file-handler>. wildfly.log still won't rotate. I noticed some weird things in our logging library, so I rolled it back to a previous version, and lo and behold, wildfly.log rotated immediately upon startup. So clearly there is something there on our side that needs examining.

However, that aside, it didn't rotate at midnight. And I discovered this is probably because we completely separated our own app logging from wildfly. So ALL of the logging in our app goes to server.log, as defined by the log4j2.xml file I showed above. The only stuff that goes to wildfly.log (defined in standalone.xml) is wildfly's own logging. So that's server shutdown and server startup. File rotation is not attempted unless something is written to the file. But now, since only wildfly writes to wildfly.log, and it only does so upon startup and shutdown, it therefore never rotates under normal running conditions. So we need a way to trigger this. I thought of adding an appender in log4j (we do that to create small, dedicate log files for specific things, while still also sending the line to the main log). I would run this right at midnight in a quartz job and then immediately remove the appender after logging a dummy line. However, I'm afraid that creating the appender and attaching it to wildfly.log even for so brief a purpose might create the same file locking conflict that the extra <file-handler> XML config did. Any ideas? Given our config above which separates app logging (one file) from wildfly logging (another file), is there a way to send a message to the wildfly log without stepping on any toes by creating file locking issues?

[James Perkins]

You could create a custom handler which extends the PeriodicRotatingFileHandler and use something to trigger the rotation like a scheduled thread. Short of that you'd need some way to trigger a lot message to force the rotation.

I should note too that WildFly 23 does support the log4j2 API. Meaning, you can use a log4j2 Logger and it will write log messages via the configuration in the logging subsystem. The only thing I don't see in your log4j2 configuration that might not work would be the deleting of the rotated files.

[Keith Brewer]

I had the sudden thought yesterday to try System.out.println() and it worked, lol. In trying to overcomplicate it, I skipped over the simpler solution. I had to put the logging subsection back almost to stock (bar a few changes here and there). Meaning I had to completely get rid of that stdout reference we had so that wildfly.log would be free to catch stdout messages. I set a quartz timer for 1 second after midnight to print a dummy line through System.out.println() and rotation fired right off.

QA is just going to have to find a way to tail our app log file output because it seems like it's just not going to work to have our logging go to a dedicated app log, AND the wildfly log, WHILE wildfly also still does its own logging, AND have the log file properly rotate. Which is fine because this solution is much cleaner and much less hacky.

[James Perkins]

Excellent. Yes, two log handlers attempting to log to the same file is going to create problems :) Please let me know if you've got further questions.

[Keith Brewer]

Actually, I kind of do! When you said:

"I should note too that WildFly 23 does support the log4j2 API. Meaning, you can use a log4j2 Logger and it will write log messages via the configuration in the logging subsystem."

What exactly do you mean by that. Something beyond what we're already doing with our log4j2.xml file in WEB-INF/classes/ to control our own app logging? Do you mean we could tweak wildfly's logging there directly, or is wildfly itself always supposed to use its own configuration from standalone.xml?

[James Perkins]

What I mean is, if you use the log4j-api, e.g. just using Logger.getLogger() to log messages, the log message will be routed via the logging subsystem. There is no support for configuring the log manager with a log4j2.xml file. If you want to do that, you need to exclude the logging subsystem from your deployment and include the log4j libraries in your deployment.

The main advantage to using the logging subsystem is you can make runtime changes that don't require a redeploy of your application or a reload of the server. For example if you want to turn on some debug logging you can use CLI or the web console to easily do that.