Access to logger when initialising statics

Post here your questions about SFS2X. Here we discuss all server-side matters. For client API questions see the dedicated forums.

Moderators: Lapo, Bax

Void*
Posts: 75
Joined: 15 Feb 2021, 13:49

Access to logger when initialising statics

Postby Void* » 30 Aug 2022, 14:02

This is probably more of a Java question than an SFS2X specific one but I'm not sure.

Essentially I'm doing some static initialisation and I wan to access a logger instance; because it's an initialiser I can't pass anything into it so I'm trying to access a logger via

Code: Select all

var loggerInstance = LoggerFactory.getLogger("someNameHere");
however, whilst nothing errors or falls over, writing to the logger instance produces no output.

I've left my log4j file in the default SFS2X state but I'll list it anyway;

Code: Select all

# ConsoleAppender
log4j.appender.consoleAppender=org.apache.log4j.ConsoleAppender
log4j.appender.consoleAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.consoleAppender.layout.ConversionPattern=%d{HH:mm:ss,SSS} %-5p [%t] %c{2} %3x - %m%n

# SocketAppender
log4j.appender.socketAppender=org.apache.log4j.net.SocketAppender
log4j.appender.socketAppender.remoteHost=localhost
log4j.appender.socketAppender.port=4445
log4j.appender.socketAppender.locationInfo=true

# Regular FileAppender
# NOTE: altering the ConversionPattern will cause a portion of the AdminTool's Log Viewer module to stop working properly
log4j.appender.fileAppender=org.apache.log4j.DailyRollingFileAppender
log4j.appender.fileAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.fileAppender.File=logs/smartfox.log
log4j.appender.fileAppender.layout.ConversionPattern=%d{dd MMM yyyy | HH:mm:ss,SSS} | %-5p | %t | %c{3} | %3x | %m%n
log4j.appender.fileAppender.Encoding=UTF-8

# The file is rolled over every day.
# Other examples:
#
# '.'yyyy-MM-dd-HH                      rolls every hour
# '.'yyyy-MM-dd-HH-mm           rolls every minute
log4j.appender.fileAppender.DatePattern='.'yyyy-MM-dd


# BootLogger FileAppender(s)
log4j.appender.bootFileAppender=org.apache.log4j.DailyRollingFileAppender
log4j.appender.bootFileAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.bootFileAppender.File=logs/boot/boot.log
log4j.appender.bootConsoleAppender.threshold=DEBUG
log4j.appender.bootFileAppender.layout.ConversionPattern=%d{dd MMM yyyy | HH:mm:ss,SSS} | %-5p | %t | %c{3} | %3x | %m%n
log4j.appender.bootFileAppender.Encoding=UTF-8

log4j.appender.bootConsoleAppender=org.apache.log4j.ConsoleAppender
log4j.appender.bootConsoleAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.bootConsoleAppender.layout.ConversionPattern=%d{HH:mm:ss,SSS} %-5p [%t] %c{3} %3x - %m%n
log4j.appender.bootConsoleAppender.threshold=WARN


# log4j.category.com.smartfoxserver.v2=DEBUG,consoleAppender,fileAppender,socketAppender
log4j.category.com.smartfoxserver=INFO,consoleAppender,fileAppender
log4j.category.org.apache=INFO,consoleAppender,fileAppender
log4j.category.org.apache.http=INFO,consoleAppender,fileAppender
log4j.category.org.eclipse.jetty=WARN,consoleAppender,fileAppender
log4j.category.bootLogger=DEBUG,bootFileAppender,bootConsoleAppender
log4j.category.sfs2x=INFO,consoleAppender,fileAppender
log4j.category.Extensions=INFO,consoleAppender,fileAppender
log4j.category.hsqldb.db=WARN,consoleAppender,fileAppender
log4j.category.jndi=INFO,consoleAppender,fileAppender


So if you were to take an example of the code I'm running it would be something akin to;

Code: Select all

pubilc class SomeManager {
  public final static List<String> someStrings = new List<String>();
  static {
    var loggerInstance = LoggerFactory.getLogger("Extensions"); // I tried various names and just ended on using categories listed in the properties file
    // Do some calculations on which strings to add from files and add them to the list
    // code code code...
    // Add a task to the scheduler
    var offset = randomBetween(3600, 7200);
    SmartFoxServer.getInstance().getTaskScheduler().schedule(new MyRunnableTask(), offset, TimeUnit.SECONDS);
    // Log the task schedule time
    loggerInstance.info("XYZ Task Scheduled to run in " + offsetSeconds + " seconds");
  }
}


Obviously this is not the exact code but should give you an idea. I've run it through the debugger and nothing is crashing. It hits the log line, then the exit brace, then everything continues running as normal. I added a printLn statement after the logger info line, which successfully printed to console just to ensure the log line itself wasn't crashing out of the initialiser.

What am I doing wrong here?

EDIT: I thought I'd add where in the actual program execution this happens; this happens as the server is starting up, it starts loading the Zone, which loads a long-lived Room, which accesses some of this static data during its `init()` method.
Last edited by Void* on 31 Aug 2022, 10:05, edited 1 time in total.
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Access to logger when initialising statics

Postby Lapo » 31 Aug 2022, 08:15

Hi,
very strange behavior. If I got this correctly, the static method is called inside the init() of an Extension?
If yes, it should definitely output the message in the logs.

Usually there's two main reasons why the logger fails to output messages:
1) It's called too early before the SFS2X API have loaded the logging config (happens before Zones are loaded)
2) There's a mismatch with the logger name (e.g. misspelled category)

Also there can be an issue with logging levels but none of these seem to apply here, so I am not sure what else could be.

Maybe double check that the compilation and deployment of the code is done without errors? Just in case you're seeing an older version of the code due to errors before the deployment.

Cheers
Lapo
--
gotoAndPlay()
...addicted to flash games
Void*
Posts: 75
Joined: 15 Feb 2021, 13:49

Re: Access to logger when initialising statics

Postby Void* » 31 Aug 2022, 09:58

Hi Lapo, all your assumptions were correct.

I did ensure that the correct code was deployed; I am using JetBrains IntelliJ as the IDE so I went through the process of ensuring a clean compilation as well, and checking that the Ant scripts were all working as they should and re-downloading any Maven/Global libraries we are using.

In the end I decided to drop the static initialiser and instead make it an initialisation function called from the Zone init() method. This has corrected the problem. To me, this makes it look like a possible JVM threading/classloader issue.
Unfortunately, with deadlines looming I don't have time to fully investigate the issue, however, I have left a source branch in it's pre-working state for investigation later.

If I find anything, I'll let you know.
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Access to logger when initialising statics

Postby Lapo » 31 Aug 2022, 14:32

Interesting, it may be what you said.
If you find out more let us know.

Cheers
Lapo

--

gotoAndPlay()

...addicted to flash games

Return to “SFS2X Questions”

Who is online

Users browsing this forum: No registered users and 76 guests