Logging in 4.7.0

Hi

Been using openfire on linux for a while, and recently updated all our instances to 4.6.6. Been evaluating the upgrade to 4.7.0, but noticed that logging is pretty much non existing in this version. stdoutt.log used to contain a bunch of INFO level messages on startup, and now only logs “Openfire 4.7.0 [<date>]” and “Admin console listening at: <urls>”. I saw there were some logging changes in OF-1840, but i cant fully understand them. I took that all log levels have been combined into this one openfire.log, but checking from the dashboard, this log is empty, and the file is only created when clicking “Mark”, but still with no logging inside.

I dont particularly care for those INFO level messages, just want to make sure that logging is working, before upgrading our instances.

Thanks

That’s curious. You are right in the sense that most log files (error.log, warn.log, info.log and debug.log) have been replaced with one file named openfire.log starting with Openfire 4.7.0, but that should not affect other logging.

The standard-out log is often pretty light, although installing specific plugins (notably those that pull in third-party solutions) might add a lot of information to that. As an example, my std-out looks like this:

./distribution/target/distribution-base/bin/openfire.sh: 21: shopt: not found
Listening for transport dt_socket at address: 5005
Missing database schema for openfire. Attempting to install...
Database update successful.
Openfire 4.7.1 Alpha [Jan 27, 2022 11:08:54 AM]
Admin console listening at:
  http://example.org:9090
  https://example.org:9091
Successfully loaded plugin 'admin'.
Successfully loaded plugin 'search'.
Finished processing all plugins.

Just booting (using the -demoboot argument, which might add some data) causes a little over 200 lines to be logged in openfire.log for me.

One outlier that I can think of that could explain some differences as compared to earlier versions is by using a different distribution to upgrade an existing server (with regards to standard-out logging, there are some differences based on the installer that is used, I believe).

The admin console lists the output directory. Can you check its content?

Also, verify the location as defined in <OPENFIRE_HOME>/lib/log4j2.xml. Note the filename: older versions of Openfire used a file called log4j.xml (without the 2), which is no longer used in newer versions of Openfire.

As a last resort, check other locations on disk that might hold log files, like /var/log/openfire. Maybe some kind of inconsistency causes the logging configuration to be, somehow, duplicated?

Sorry for the late reply, some other stuff got in the way.

Server has been up since i posted. stdoutt.log still only has those lines and openfire.log is still empty.

We are using the binary from the tarball. Pretty basic startup service:

# /etc/systemd/system/openfire.service

[Unit]
Description=Openfire XMPP Server
After=network-online.target

[Service]
EnvironmentFile=/etc/default/openfire
Type=forking
ExecStart=/opt/openfire/current/bin/openfire start
ExecStop=/opt/openfire/current/bin/openfire stop
WorkingDirectory=/opt/openfire/current
User=openfire
Group=openfire

[Install]
WantedBy=default.target
# /etc/default/openfire 

JAVA_HOME="/opt/jvm/current/jre"
PATH="/opt/jvm/current/jre/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"

We have a couple of java startup options, from the log4j mitigation, but already tried without those without any changes:

# /opt/openfire/current/bin/openfire.vmoptions 

-Dlog4j.configurationFile=${sys:openfire.lib.dir}/log4j2.xml -Dlog4j2.formatMsgNoLookups=true
openfire 19623     1  0 Jan24 ?        00:39:50 /opt/jvm/current/jre/bin/java -server -Djdk.tls.ephemeralDHKeySize=matched -Djsse.SSLEngine.acceptLargeFragments=true -DopenfireHome=/opt/openfire/current/bin/../ -Dopenfire.lib.dir=/opt/openfire/current/lib -Dlog4j.configurationFile=${sys:openfire.lib.dir}/log4j2.xml -Dlog4j2.formatMsgNoLookups=true -Di4jv=0 -Di4jv=0 -Di4jv=0 -Di4jv=0 -classpath /opt/openfire/current/.install4j/i4jruntime.jar:/opt/openfire/current/.install4j/launchere44106de.jar:/opt/openfire/current/lib/* install4j.org.jivesoftware.openfire.starter.ServerStarter start
Environment
Java Version: 	1.8.0_312 Azul Systems, Inc. -- OpenJDK 64-Bit Server VM
Appserver: 	jetty/9.4.43.v20210629 

# ls -la /opt/openfire/
total 0
drwxr-xr-x  4 root     root      47 Jan 24 12:49 .
drwxr-xr-x  8 root     root      88 Sep 24 18:22 ..
drwxr-x--- 11 openfire openfire 203 Dec 17 09:22 4.6.6
drwxr-x--- 11 openfire openfire 203 Jan 24 12:49 4.7.0
lrwxrwxrwx  1 root     root      19 Jan 24 12:19 current -> /opt/openfire/4.7.0

# ls -la /opt/openfire/current/
total 396
drwxr-x--- 11 openfire openfire    203 Jan 24 12:49 .
drwxr-xr-x  4 root     root         47 Jan 24 12:49 ..
drwxr-x---  3 openfire openfire    108 Feb  7 12:26 bin
-rw-r--r--  1 openfire openfire 364493 Jan 19 17:46 changelog.html
drwxr-xr-x  2 openfire openfire     99 Feb  7 12:26 conf
drwxr-xr-x  4 openfire openfire   4096 Jan 19 17:47 documentation
drwxr-x---  3 openfire openfire    116 Feb  7 12:26 embedded-db
drwxr-xr-x  2 openfire openfire   4096 Jan 19 17:47 .install4j
drwxr-xr-x  2 openfire openfire   8192 Jan 19 17:47 lib
-rw-r--r--  1 openfire openfire  10874 Jan  5 16:24 LICENSE.html
drwxr-xr-x  2 openfire openfire     65 Jan 24 13:36 logs
drwxr-xr-x  4 openfire openfire     51 Jan 24 12:49 plugins
-rw-r--r--  1 openfire openfire   5403 Jan  5 16:24 README.html
drwxr-xr-x  6 openfire openfire     69 Jan 19 17:47 resources

# /opt/openfire/current/lib/log4j2.xml 
<?xml version="1.0" encoding="UTF-8"?>

<Configuration monitorInterval="30">
    <Appenders>
        <!-- Modifying this appender is likely to break the log viewer that is part of the Openfire admin console.
           - If you'd like to have a differently formatted log file, it is advisable to create a new log file, by
           - duplicating this configuration, instead of changing it.
          -->
        <RollingFile name="openfire" fileName="${sys:openfireHome}/logs/openfire.log" filePattern="${sys:openfireHome}/logs/openfire.log-%i">
            <PatternLayout>
                <Pattern>%d{yyyy.MM.dd HH:mm:ss} %highlight{%-5p} [%t]: %c - %msg{nolookups}%n</Pattern>
            </PatternLayout>
            <Policies>
                <SizeBasedTriggeringPolicy size="100 MB"/>
            </Policies>
        </RollingFile>

        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="%msg{nolookups}%n%throwable{0}"/>
        </Console>
        
    </Appenders>

    <Loggers>
        <!-- OF-1095: Uniform output of loading/unloading of plugins to std-out. -->
        <Logger name="org.jivesoftware.openfire.container.PluginManager">
            <AppenderRef ref="console"/>
        </Logger>
        <Logger name="org.jivesoftware.openfire.container.PluginMonitor">
            <AppenderRef ref="console"/>
        </Logger>

        <!-- OF-506: Jetty INFO messages are generally not useful. Ignore them by default. -->
        <Logger name="org.eclipse.jetty" level="warn"/>

        <Root level="info">
            <AppenderRef ref="openfire"/>
        </Root>
    </Loggers>
</Configuration>

# ls -la /opt/openfire/current/logs/
total 8
drwxr-xr-x  2 openfire openfire  65 Jan 24 13:36 .
drwxr-x--- 11 openfire openfire 203 Jan 24 12:49 ..
-rw-r--r--  1 openfire openfire   0 Jan 24 13:45 openfire.log
-rw-r--r--  1 openfire openfire 101 Jan 24 13:37 stderror.log
-rw-r--r--  1 openfire openfire 126 Jan 24 13:37 stdoutt.log

Let me know if there is anything else i could check

Curious. I can’t immediately spot something off.

Although I have no reason to believe that it is problematic, I’m noticing that you use a symlink. Openfire’s admin console shows the symlink target (/opt/openfire/4.7.0/) while you’re start/stopping using the symlink name (/opt/openfire/current/). Maybe that somehow confuses log4j? Have you tried without symlinks, or, alternatively, tried modifying the log4j2.xml file to not use the openfireHome system variable, but a a direct path instead?

We’ve been using that folder/symlink structure and services for a long time.

In any case, i just tried overriding the dirs in log4j2.xml with this:
<RollingFile name="openfire" fileName="/opt/openfire/current/logs/openfire.log" filePattern="/opt/openfire/current/logs/openfire.log-%i">
…and no changes. Dashboard still shows 4.7.0/logs and openfire.log is untouched.

Also tried changing the start path of the binary, and reverting log4j2.xml to default, and same result:

# ps -ef|grep openfire
openfire 16989     1 73 13:25 ?        00:00:21 /opt/jvm/current/jre/bin/java -server -Djdk.tls.ephemeralDHKeySize=matched -Djsse.SSLEngine.acceptLargeFragments=true -DopenfireHome=/opt/openfire/4.7.0/bin/../ -Dopenfire.lib.dir=/opt/openfire/4.7.0/lib -classpath /opt/openfire/4.7.0/.install4j/i4jruntime.jar:/opt/openfire/4.7.0/.install4j/launchere44106de.jar:/opt/openfire/4.7.0/lib/* install4j.org.jivesoftware.openfire.starter.ServerStarter start


# ls -la 4.7.0/logs/
total 8
drwxr-xr-x  2 openfire openfire  65 Jan 24 13:36 .
drwxr-x--- 11 openfire openfire 203 Jan 24 12:49 ..
-rw-r--r--  1 openfire openfire   0 Jan 24 13:45 openfire.log
-rw-r--r--  1 openfire openfire  32 Feb  7 13:25 stderror.log
-rw-r--r--  1 openfire openfire 125 Feb  7 13:25 stdoutt.log

Have you tried debugging the log4j configuration? Maybe that includes useful hints. See Log4j – Frequently Asked Questions

Interesting…I’ve set the -Dlog4j2.debug=true in vmoptions and it did write a bunch of stuff to stderr.log. More importantly, in the middle of it, there are these lines:

TRACE StatusLogger Trying to find [log4j2.xml] using context class loader sun.misc.Launcher$AppClassLoader@15db9742.
TRACE StatusLogger Trying to find [log4j2.xml] using sun.misc.Launcher$AppClassLoader@15db9742 class loader.
TRACE StatusLogger Trying to find [log4j2.xml] using sun.misc.Launcher$AppClassLoader@15db9742 class loader.
TRACE StatusLogger Trying to find [log4j2.xml] using ClassLoader.getSystemResource().
WARN StatusLogger No Log4j 2 configuration file found. Using default configuration (logging only errors to the console), or user programmatically provided configurations. Set system property ‘log4j2.debug’ to show Log4j 2 internal initialization logging. See Log4j – Configuring Log4j 2 for instructions on how to configure Log4j 2

The weird thing is, that according to the link above, it should look for a log4j2.xml file in the classpath, but that doesnt seem to be working

openfire 28089 1 5 14:40 ? 00:00:24 /opt/jvm/current/jre/bin/java -server -Djdk.tls.ephemeralDHKeySize=matched -Djsse.SSLEngine.acceptLargeFragments=true -DopenfireHome=/opt/openfire/current/bin/../ -Dopenfire.lib.dir=/opt/openfire/current/lib -Dlog4j2.debug=true -classpath /opt/openfire/current/.install4j/i4jruntime.jar:/opt/openfire/current/.install4j/launchere44106de.jar:/opt/openfire/current/lib/* install4j.org.jivesoftware.openfire.starter.ServerStarter start

# ls -la /opt/openfire/current/lib/log4j*
-rw-r--r-- 1 openfire openfire    1641 Feb  7 13:24 /opt/openfire/current/lib/log4j2.xml
-rw-r--r-- 1 openfire openfire  301872 Jan  3 23:11 /opt/openfire/current/lib/log4j-api-2.17.1.jar
-rw-r--r-- 1 openfire openfire 1790452 Jan  3 23:11 /opt/openfire/current/lib/log4j-core-2.17.1.jar
-rw-r--r-- 1 openfire openfire   24279 Jan  3 23:11 /opt/openfire/current/lib/log4j-slf4j-impl-2.17.1.jar

I have also tried setting -Dlog4j2.configurationFile=${sys:openfire.lib.dir}/log4j2.xml and -Dlog4j2.configurationFile=/opt/openfire/4.7.0/lib/log4j2.xml, but none of them fixed the issue. Also, when i tried setting those vmoptions together with -Dlog4j2.debug=true, it just made the log4j debug stop working.

I still cant put my finger where the issue could be

It’s weird that the configuration can’t be found on the classpath, but it shouldn’t be needed to locate that on the classpath when it’s being referenced by a -Dlog4j.configurationFile argument.

I noticed in an earlier post that you added -Dlog4j.configurationFile=${sys:openfire.lib.dir}/log4j2.xml as an argument. I’m not sure if ${sys:openfire.lib.dir} can be expected to work when provided as an argument to the Java process. Maybe replace that with a more direct file reference?

When I start Openfire in demoboot on my local machine (based on a development build, which is not using the Install4j launcher, so might be different), this is what’s being executed:

/usr/lib/jvm/java-8-openjdk-amd64/bin/java \
-Dlog4j.configurationFile=/home/guus/SourceCode/IgniteRealtime/Openfire/distribution/target/distribution-base/lib/log4j2.xml \
-Dlog4j2.formatMsgNoLookups=true \
-Djdk.tls.ephemeralDHKeySize=matched \
-Djsse.SSLEngine.acceptLargeFragments=true \
-server \
-DopenfireHome=/home/guus/SourceCode/IgniteRealtime/Openfire/distribution/target/distribution-base \
-Dopenfire.lib.dir=/home/guus/SourceCode/IgniteRealtime/Openfire/distribution/target/distribution-base/lib \
-classpath /home/guus/SourceCode/IgniteRealtime/Openfire/distribution/target/distribution-base/lib/startup.jar \
-jar /home/guus/SourceCode/IgniteRealtime/Openfire/distribution/target/distribution-base/lib/startup.jar

The classpath here is limited to only the startup.jar - not even the other libraries.

I just realized that we have been referencing to “log4j.configurationFile” and “log4j2.configurationFile”. Many sources online mention the former, but apache log4j docs that are linked above, mention the latter.

Log4j will inspect the “log4j2.configurationFile” system property and, if set, will attempt to load the configuration using the ConfigurationFactory that matches the file extension. Note that this is not restricted to a location on the local file system and may contain a URL.
Log4j – Configuring Log4j 2

In any case, I tried with both of those settings, and also with the direct path, like I mentioned in the previous post, and no luck. As soon as I set any of those vars, the log4j debug stops working, and neither of them fixes the logging issue i described in the op.

# ps -ef|grep openfire
openfire 15478     1 32 17:41 ?        00:00:00 /opt/jvm/current/jre/bin/java -server -Djdk.tls.ephemeralDHKeySize=matched -Djsse.SSLEngine.acceptLargeFragments=true -DopenfireHome=/opt/openfire/current/bin/../ -Dopenfire.lib.dir=/opt/openfire/current/lib -Dlog4j2.debug=true -Dlog4j.configurationFile=/opt/openfire/current/lib/log4j2.xml -Di4jv=0 -Di4jv=0 -Di4jv=0 -Di4jv=0 -classpath /opt/openfire/current/.install4j/i4jruntime.jar:/opt/openfire/current/.install4j/launchere44106de.jar:/opt/openfire/current/lib/* install4j.org.jivesoftware.openfire.starter.ServerStarter start
# ls -la logs/
total 4
drwxr-xr-x  2 openfire openfire  25 Feb  7 17:41 .
drwxr-x--- 11 openfire openfire 203 Jan 24 12:49 ..
-rw-r--r--  1 openfire openfire 125 Feb  7 17:41 stdoutt.log

@Neustradamus this has very little to do with the very specific problem that is being discussed here. Do not take away focus of the issue at hand for your own benefit.

I have been able to reproduce this problem. I think it’s an omission in the Install4j-generated launcher called ‘openfire’. I’ve raised [OF-2392] - Ignite Realtime Jira to track this issue. A fix is in the works in https://github.com/igniterealtime/Openfire/pull/2001. I’m aiming to get this included in Openfire 4.7.1.

@jonybat Can you confirm that the problem has been resolved in the nightly builds of Feb 15th and later?

Thanks for looking deeper at this.

I have just did some tests with the nightly from 16-02-2022, and here are my results:

  • openfire.log now has contents and seems to have the INFO level startup messages from before and even ERROR messages from client connections, so all good here
  • no issues with symlinks, as suspected
  • something is broken in this build, because it will only start properly on first setup. As soon as the setup is done (<setup>true</setup>, conf/openfire.xml) and the server is restarted, it will no longer write anything to logs or listen on dashboard or any other port

As a bonus, i realized that the dashboard log viewer wasnt working for me because it was being blocked by an ad blocker.

1 Like

Noticed 4.7.1 was just released. Did a quick test, and it looks good. Starts without issues and logging is working as i mentioned in the previous post.

Only thing i had to do is remove the openfire.vmoptions we had, otherwise it would go back to the same logging issue. I guess those are not needed anymore, since those properties have been added to the launcher in that commit you posted.

Thanks for the help and quick fix :+1:

1 Like

Thanks for your quick verification.

This might be the same issue as the one reported by @totzkotz in https://discourse.igniterealtime.org/t/npe-in-setup-of4-8-master-03-feb/ which affects the prereleases of 4.8.0, but not 4.7.x. I’ve created OF-2391 for that issue. Do you see NPEs in the logs?

I have removed the nightly build installation and respective logs, but i dont remember seeing any NPEs. Even when i started the server directly (without systemd or env vars), from bin/openfire run, the only thing logged to the console was something like “Starting server”, and then nothing