Excessive logging despite log4j.properties

[kreotak]

Description

We configures the log4j.properties to just log ERROR for the root Logger. But this doesn't seem to work because we get around 800MB of Logs for our nightly test run (Level INFO and above).

The startup log indicates that the log4j configuration was read, but directly after that replaced by the default configuration.

Log output

log4j: Using URL [file:/opt/selenium/log4j.properties] for automatic log4j configuration. log4j: Reading configuration from URL file:/opt/selenium/log4j.properties log4j: Parsing for [root] with value=[ERROR, FILE]. log4j: Level token is [ERROR]. log4j: Category root set to ERROR log4j: Parsing appender named "FILE". log4j: Parsed "FILE" options. log4j: Finished configuring. log4j: Reading configuration from URL jar:file:/opt/selenium/SeleniumGridExtras-1.11.8-SNAPSHOT-jar-with-dependencies.jar!/log4j.properties log4j: Parsing for [root] with value=[INFO, FILE]. log4j: Level token is [INFO]. log4j: Category root set to INFO log4j: Parsing appender named "FILE". log4j: Parsing layout options for "FILE". log4j: Setting property [conversionPattern] to [%d{dd MMM yyyy HH:mm:ss} [%t] %-5p %c{2} %x - %m%n]. log4j: End of parsing for "FILE". log4j: Setting property [fileNamePattern] to [log//grid_extras.%d{yyyy-MM-dd}.log]. log4j: setFile called: log//grid_extras.2016-01-05.log, true log4j: setFile ended log4j: Parsed "FILE" options. log4j: Finished configuring.

[smccarthy]

Did you go through these steps ? https://github.com/groupon/Selenium-Grid-Extras#changing-the-logging-on-the-grid-hub-nodes-or-selenium-grid-extras

You can change the logging for selenium and selenium-grid-extras separately.

[kreotak]

Hello,

yes, the logging was configures using the link provided. The log configuration for selenium (hub+node) is working as expected, but for the selenium-grid-extras our configuration is loaded (visible in the provided log excerpt) but gets overwritten by the properties from the jarfile itself (if the log is correct).

[smccarthy]

@kreotak I tried it, and it works for me... can you paste your log4j.properties file here, as well as the exact command you use to start your selenium grid extras jar?

My command I use to start the jar: java -Dlog4j.debug -Dlog4j.configuration=file:log4j.properties -cp .:SeleniumGridExtras-1.11.8-SNAPSHOT-jar-with-dependencies.jar com.groupon.seleniumgridextras.SeleniumGridExtras

My log4j.properties:

Define the root logger with appender file

log = log/ log4j.rootLogger = ERROR, FILE

Define the file appender

log4j.appender.FILE=org.apache.log4j.rolling.RollingFileAppender log4j.appender.FILE.rollingPolicy=org.apache.log4j.rolling.TimeBasedRollingPolicy log4j.appender.FILE.rollingPolicy.FileNamePattern=${log}/grid_extras.%d{yyyy-MM-dd}.log

Define the layout for file appender

log4j.appender.FILE.layout=org.apache.log4j.PatternLayout log4j.appender.FILE.layout.ConversionPattern=%d{dd MMM yyyy HH:mm:ss} [%t] %-5p %c{2} %x - %m%n

[kreotak]

@smccarthy Our log4j.properties is exactly the same and our startup command (almost) too:

java -Xms1024m -Xmx4096m -Dlog4j.debug -Dlog4j.configuration=file:/opt/selenium/log4j.properties -jar /opt/selenium/SeleniumGridExtras-1.11.8-SNAPSHOT-jar-with-dependencies.jar com.groupon.seleniumgridextras.SeleniumGridExtras

I do not think that the memory configuration affects the logging.

Immediatly on startup the grid_extras Logfile gets filled with INFO logs like:

12 Jan 2016 08:04:00 [main] INFO seleniumgridextras.SeleniumGridExtras - Loaded Grid Logger from log4j.properties 12 Jan 2016 08:04:00 [main] INFO remote.ConfigPuller - Config file storing central repository URL is /opt/selenium/configs/central_config_repo_config.txt 12 Jan 2016 08:04:00 [main] INFO remote.ConfigPuller - Config file for central repo does not exist /opt/selenium/configs/central_config_repo_config.txt 12 Jan 2016 08:04:00 [main] INFO remote.ConfigPuller - Central config URL for current node is set to '' 12 Jan 2016 08:04:00 [main] INFO remote.ConfigPuller - The central config URL is empty, will not download the latest configs.

[smccarthy]

Hi @kreotak Your command uses -jar, but I use -cp.

Try this please: java -Xms1024m -Xmx4096m -Dlog4j.debug -Dlog4j.configuration=file:/opt/selenium/log4j.properties -cp .:SeleniumGridExtras-1.11.8-SNAPSHOT-jar-with-dependencies.jar com.groupon.seleniumgridextras.SeleniumGridExtras

[kreotak]

Hi @smccarthy , I changed it to

java -Xms1024m -Xmx4096m -Dlog4j.debug -Dlog4j.configuration=file:/opt/selenium/log4j.properties -cp .:/opt/selenium/SeleniumGridExtras-1.11.8-SNAPSHOT-jar-with-dependencies.jar com.groupon.seleniumgridextras.SeleniumGridExtras

The logging got indeed a bit less, but there are still some INFO present, most of them are:

INFO video.RemoteVideoRecordingControlCallable

It seems like the application is trying to create a video callable, but video recording was disabled in the grid_extras JSON configuration.

[dave-miles]

The following hack ensures I get the logging I require:

zip SeleniumGridExtras-1.12.2-SNAPSHOT-jar-with-dependencies.jar log4j.properties

Did this since the jar log4j.properties in the jar is overriding the custom settings set in the file:

log4j: Using URL [file:log4j.properties] for automatic log4j configuration.
log4j: Reading configuration from URL file:log4j.properties
log4j: Parsing for [root] with value=[FATAL, FILE].
log4j: Level token is [FATAL].
log4j: Category root set to FATAL
log4j: Parsing appender named "FILE".
log4j: Parsing layout options for "FILE".
log4j: Setting property [conversionPattern] to [%d{dd MMM yyyy HH:mm:ss} [%t] %-5p %c{2} %x - %m%n].
log4j: End of parsing for "FILE".
log4j: Setting property [fileNamePattern] to [log//grid_extras.%d{yyyy-MM-dd}.log].
log4j: setFile called: log//grid_extras.2016-09-17.log, true
log4j: setFile ended
log4j: Parsed "FILE" options.
log4j: Finished configuring.
log4j: Reading configuration from URL jar:file:/opt/selenium/sehub4444/SeleniumGridExtras-1.12.2-SNAPSHOT-jar-with-dependencies.jar!/log4j.properties
log4j: Parsing for [root] with value=[INFO, FILE].
log4j: Level token is [INFO].
log4j: Category root set to INFO
log4j: Parsing appender named "FILE".
log4j: Parsing layout options for "FILE".
log4j: Setting property [conversionPattern] to [%d{dd MMM yyyy HH:mm:ss} [%t] %-5p %c{2} %x - %m%n].
log4j: End of parsing for "FILE".
log4j: Setting property [fileNamePattern] to [log//grid_extras.%d{yyyy-MM-dd}.log].
log4j: setFile called: log//grid_extras.2016-09-17.log, true
log4j: setFile ended
log4j: Parsed "FILE" options.
log4j: Finished configuring.

Also the log4j version bundled is now deprecated, would a later version resolve all of this?

unzip -p SeleniumGridExtras-1.12.2-SNAPSHOT-jar-with-dependencies.jar  META-INF/maven/log4j/log4j/pom.xml

  <name>Apache Log4j</name>
  <version>1.2.17</version>
  <description>Apache Log4j 1.2</description>
  <url>http://logging.apache.org/log4j/1.2/</url>

[smccarthy]

@dave-miles A later version might help, I am not sure though. I am not familiar with the "zip" command you mentioned. Doesn't my workarounds I mentioned work as well? Or are you still seeing some INFO logs when you shouldn't (like kreotak ?) If someone wants to try out newer versions of log4j and make a PR, I would be glad to accept it.

[benzman81]

I guess its because of this line: PropertyConfigurator.configure(SeleniumGridExtras.class.getClassLoader().getResource(filename)); in the main method. Seems to override the othe file. Stumbled across this bug today. Will try the zip, too.