logging-log4j-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Никита Глухов <tikan...@gmail.com>
Subject Why Log4J2 root logger consumes all log levels from the child loggers
Date Thu, 07 Jun 2018 19:33:27 GMT
Project at job (written in Java) uses:

   1. spring-context 5.0.6
   2. spring-test 5.0.6
   3. log4j-api 2.11
   4. log4j-core 2.11
   5. log4j-jcl (as a bridge to get log events from Spring's bowels and to
   utilize logger in test classes, obtained from extending
   *AbstractTestNGSpringContextTests*)
   6.

   ... and some other dependencies like Selenium, MyBatis, TestNG to write
   autotests ...

   So, I wrote YAML configuration file and everything works as I want
   (loggers bind to appenders, appenders write log data to files), but root
   logger consumes all log events from child loggers even if its own log level
   is WARN and child's one is DEBUG or TRACE. Of course, I can use workaround
   - simply set *additivity* to *false*, but I don't like to turn off log
   event propagation - it is quite useful and that's why I want root logger to
   behave as expected by default - to pass *more* specific log levels and
   ignore *less* specific log events from the child loggers.
   Clarify this, please.
   Thanks in advance.

*YAML configuration file: *

Configuration:
  name: samsonpost-logging-configuration

  Properties:
    Property:
      name: log-path
      value: "logs"

  Appenders:
    Console:
      name: stdout
      target: SYSTEM_OUT
      PatternLayout:
        pattern: "%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p - %m%n"

    File:
      - name: sp_sql
        filename: ${log-path}/sp_sql.log
        append: false
        immediateFlush: true
        PatternLayout:
          pattern: "%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p - %m%n"

      - name: php_execute_script
        filename: ${log-path}/php_execute_script.log
        append: false
        PatternLayout:
          pattern: "%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p - %m%n"

      - name: js_execute_script
        filename: ${log-path}/js_execute_script.log
        append: false
        PatternLayout:
          pattern: "%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p - %m%n"

      - name: test
        filename: ${log-path}/test.log
        append: false
        PatternLayout:
          pattern: "%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p - %m%n"

      - name: log_files_operation
        filename: ${log-path}/log_files_operation.log
        append: false
        PatternLayout:
          pattern: "%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p - %m%n"

      - name: webdriver
        filename: ${log-path}/webdriver.log
        append: false
        PatternLayout:
          pattern: "%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p - %m%n"
  Loggers:
    Root:
      level: WARN
      AppenderRef:
        ref: stdout

    Logger:
      - name: ExecutePHPScript
        level: DEBUG
        AppenderRef:
          ref: php_execute_script

      - name: ExecuteJSScript
        level: DEBUG
        AppenderRef:
          ref: js_execute_script

      - name: services
        level: INFO
        AppenderRef:
          ref: test

      - name: db.entity.sp.core
        level: DEBUG
        additivity: false
        AppenderRef:
          ref: sp_sql

      - name: wd
        level: DEBUG
        additivity: false
        AppenderRef:
          ref: webdriver

*POM.xml*

<?xml version="1.0" encoding="UTF-8"?><project
xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0
http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>samsonpost</groupId>
    <artifactId>samsonpost-htmlelements</artifactId>
    <version>1.0-SNAPSHOT</version>
    <properties>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
        <aspectj.version>1.8.5</aspectj.version>
        <maven.compiler.source>1.8</maven.compiler.source>
        <maven.compiler.target>1.8</maven.compiler.target>
        <org.springframework.version>5.0.6.RELEASE</org.springframework.version>
    </properties>
    <dependencies>
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-api</artifactId>
            <version>2.11.0</version>
        </dependency>
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-core</artifactId>
            <version>2.11.0</version>
            <scope>runtime</scope>
        </dependency>
        <dependency>
            <groupId>ru.yandex.qatools.htmlelements</groupId>
            <artifactId>htmlelements-java</artifactId>
            <version>1.19</version>
        </dependency>
        <dependency>
            <groupId>org.seleniumhq.selenium</groupId>
            <artifactId>selenium-java</artifactId>
            <version>3.12.0</version>
        </dependency>
        <dependency>
            <groupId>mysql</groupId>
            <artifactId>mysql-connector-java</artifactId>
            <version>5.1.46</version>
        </dependency>
        <dependency>
            <groupId>org.testng</groupId>
            <artifactId>testng</artifactId>
            <version>6.14.3</version>
            <scope>test</scope>
        </dependency>
        <dependency>
            <groupId>com.alibaba</groupId>
            <artifactId>fastjson</artifactId>
            <version>1.2.33</version>
        </dependency>
        <dependency>
            <groupId>org.mybatis</groupId>
            <artifactId>mybatis-spring</artifactId>
            <version>1.3.2</version>
        </dependency>
        <dependency>
            <groupId>org.mybatis</groupId>
            <artifactId>mybatis</artifactId>
            <version>3.4.6</version>
        </dependency>
        <dependency>
            <groupId>org.aspectj</groupId>
            <artifactId>aspectjweaver</artifactId>
            <version>1.8.13</version>
        </dependency>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-context</artifactId>
            <version>${org.springframework.version}</version>
        </dependency>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-tx</artifactId>
            <version>${org.springframework.version}</version>
            <scope>runtime</scope>
        </dependency>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-test</artifactId>
            <version>${org.springframework.version}</version>
            <scope>runtime</scope>
        </dependency>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-jdbc</artifactId>
            <version>${org.springframework.version}</version>
            <scope>runtime</scope>
        </dependency>
        <dependency>
            <groupId>com.fasterxml.jackson.core</groupId>
            <artifactId>jackson-databind</artifactId>
            <version>2.9.5</version>
            <scope>runtime</scope>
        </dependency>
        <dependency>
            <groupId>com.fasterxml.jackson.dataformat</groupId>
            <artifactId>jackson-dataformat-yaml</artifactId>
            <version>2.9.5</version>
            <scope>runtime</scope>
        </dependency>
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-jcl</artifactId>
            <version>2.11.0</version>
            <scope>runtime</scope>
        </dependency>
    </dependencies>
    <build>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-surefire-plugin</artifactId>
                <version>2.21.0</version>
                <dependencies>
                    <dependency>
                        <groupId>org.apache.maven.surefire</groupId>
                        <artifactId>surefire-testng</artifactId>
                        <version>2.21.0</version>
                    </dependency>
                </dependencies>
            </plugin>
        </plugins>
    </build></project>

*Example of a test class:*

package services.requestInt;
import common.UserID;import constants.UrlsConst;import
db.entity.sp.services.requestInt.RequestIntService;import
org.openqa.selenium.By;import org.openqa.selenium.WebDriver;import
org.springframework.beans.factory.annotation.Autowired;import
org.springframework.test.context.ContextConfiguration;import
org.springframework.test.context.testng.AbstractTestNGSpringContextTests;import
org.testng.annotations.Test;import
po.sp.blocks.popUpWindow.SelectionPopUp;import
po.sp.blocks.popUpWindow.elements.SelectUserPopUpElements;import
po.sp.pages.authorization.AuthorizePage;import
po.sp.pages.services.documents.softdev.IntCreateNewOrderPage;import
po.sp.pages.services.documents.softdev.IntDetailOrderPage;import
po.sp.pages.services.documents.softdev.IntListOrderPage;import
project.init.SpringConfiguration;import wd.wait.DriverWaitElement;
import static constants.UrlsConst.LIST_REQUEST_INT_PORTAL;import
static services.requestInt.cfg.RequestIntMissionProperty.*;
@ContextConfiguration(classes = SpringConfiguration.class)public class
RejectOrderByManagerOrApprover extends
AbstractTestNGSpringContextTests {

    @Autowired private IntListOrderPage intListOrderPage;
    @Autowired private IntCreateNewOrderPage intCreateNewOrderPage;
    @Autowired private IntDetailOrderPage intDetailOrderPage;
    @Autowired private SelectionPopUp<SelectUserPopUpElements> popUpSelectUser;
    @Autowired private AuthorizePage authorizePage;
    @Autowired private WebDriver driver;
    @Autowired private RequestIntService requestIntService;

    private Integer orderOrdinalNumber;

    @Test
    public void createOrder() {
        logger.info("Создаём заказ под Грибановым и отправляем
менеджеру на согласование");
        authorizePage.authById(UserID.GRIBANOV.getUserId());
        driver.get(LIST_REQUEST_INT_PORTAL);
        DriverWaitElement.waitElementToBeClickable(driver,
By.xpath(".//a[@for-tests='link-create']"), 15);
        intListOrderPage.createNewOrder();
        driver.switchTo().frame(driver.findElement(By.cssSelector(".side-panel-iframe")));
        intCreateNewOrderPage.selectProject(PROJECT_NAME);
        intCreateNewOrderPage.setProblem(SITE_PROBLEM);
        intCreateNewOrderPage.setSolution(SITE_SOLUTION);
        intCreateNewOrderPage.addApprover();
        popUpSelectUser.setUser("Верещагин");
        popUpSelectUser.clickUserById(UserID.VERETSHAGIN);
        intCreateNewOrderPage.saveOrder();
        intDetailOrderPage.sendToManagerForApproval();
    }

    @Test(dependsOnMethods = "createOrder")
    public void rejectByManager() {
        logger.info("Авторизуемся под менеджером (Новосельцев)
и
отклоняем заказ");
        authorizePage.authById(UserID.NOVOSELTSEV.getUserId());
        orderOrdinalNumber =
Integer.valueOf(requestIntService.findLastRequest().getCode());
        driver.get(UrlsConst.DETAIL_REQUEST_INT_PORTAL +
orderOrdinalNumber.toString() + "&IFRAME=Y&IFRAME_TYPE=SIDE_SLIDER");
        intDetailOrderPage.clickButtonRejectByManager();
        // Авторизуемся под Грибановым, вводим описание
проблемы
        logger.info("Авторизуемся под Грибановым, вводим описание
проблемы, отправляем менеджеру на согласование");
        authorizePage.authById(UserID.GRIBANOV.getUserId());
        driver.get(UrlsConst.DETAIL_REQUEST_INT_PORTAL +
orderOrdinalNumber.toString() + "&IFRAME=Y&IFRAME_TYPE=SIDE_SLIDER");
        intDetailOrderPage.clickButtonEdit();
        intCreateNewOrderPage.setProblem(SITE_REJECT_PROBLEM);
        intCreateNewOrderPage.attachFile(FILE_UPLOAD);
        intCreateNewOrderPage.saveOrder();
        intDetailOrderPage.sendToManagerForApproval();
        // Авторизуемся под Новосельцевым и согласовываем
        logger.info("Авторизуемся под мендежером (Новосельцев)
и
согласовываем");
        authorizePage.authById(UserID.NOVOSELTSEV.getUserId());
        driver.get(UrlsConst.DETAIL_REQUEST_INT_PORTAL +
orderOrdinalNumber.toString() + "&IFRAME=Y&IFRAME_TYPE=SIDE_SLIDER");
        intDetailOrderPage.clickButtonApprove();
        // Авторизуемся под Верещагиным и отклоняем
        logger.info("Авторизуемся под Верещагиным и отклоняем");
        authorizePage.authById(UserID.VERETSHAGIN.getUserId());
        driver.get(UrlsConst.DETAIL_REQUEST_INT_PORTAL +
orderOrdinalNumber.toString() + "&IFRAME=Y&IFRAME_TYPE=SIDE_SLIDER");
        intDetailOrderPage.setCommentToTask("Захотел и отменил!");
        intDetailOrderPage.clickButtonRejectByApprover();
        // Авторизуемся под Грибановым
        logger.info("Авторизуемся под Грибановым");
        authorizePage.authById(UserID.GRIBANOV.getUserId());
        driver.get(UrlsConst.DETAIL_REQUEST_INT_PORTAL +
orderOrdinalNumber.toString() + "&IFRAME=Y&IFRAME_TYPE=SIDE_SLIDER");
        intDetailOrderPage.clickButtonEdit();
        intCreateNewOrderPage.setProblem("Ну такое себе");
        intCreateNewOrderPage.saveOrder();
    }}

*stdout output:*

"C:\Program Files\Java\jdk-9.0.4\bin\java" -ea
-Dspring.profiles.active=chrome -Dlog4j2.disableJmx=true
-Didea.test.cyclic.buffer.size=1048576 "-javaagent:C:\Program
Files\JetBrains\IntelliJ IDEA 2018.1\lib\idea_rt.jar=53036:C:\Program
Files\JetBrains\IntelliJ IDEA 2018.1\bin" -Dfile.encoding=UTF-8
-classpath "C:\Program Files\JetBrains\IntelliJ IDEA
2018.1\lib\idea_rt.jar;C:\Program Files\JetBrains\IntelliJ IDEA
2018.1\plugins\testng\lib\testng-plugin.jar;D:\samsonpost\target\test-classes;D:\samsonpost\target\classes;C:\Users\glukhov\.m2\repository\ru\yandex\qatools\htmlelements\htmlelements-java\1.19\htmlelements-java-1.19.jar;C:\Users\glukhov\.m2\repository\org\seleniumhq\selenium\selenium-java\3.12.0\selenium-java-3.12.0.jar;C:\Users\glukhov\.m2\repository\org\seleniumhq\selenium\selenium-api\3.12.0\selenium-api-3.12.0.jar;C:\Users\glukhov\.m2\repository\org\seleniumhq\selenium\selenium-chrome-driver\3.12.0\selenium-chrome-driver-3.12.0.jar;C:\Users\glukhov\.m2\repository\org\seleniumhq\selenium\selenium-edge-driver\3.12.0\selenium-edge-driver-3.12.0.jar;C:\Users\glukhov\.m2\repository\org\seleniumhq\selenium\selenium-firefox-driver\3.12.0\selenium-firefox-driver-3.12.0.jar;C:\Users\glukhov\.m2\repository\org\seleniumhq\selenium\selenium-ie-driver\3.12.0\selenium-ie-driver-3.12.0.jar;C:\Users\glukhov\.m2\repository\org\seleniumhq\selenium\selenium-opera-driver\3.12.0\selenium-opera-driver-3.12.0.jar;C:\Users\glukhov\.m2\repository\org\seleniumhq\selenium\selenium-remote-driver\3.12.0\selenium-remote-driver-3.12.0.jar;C:\Users\glukhov\.m2\repository\org\seleniumhq\selenium\selenium-safari-driver\3.12.0\selenium-safari-driver-3.12.0.jar;C:\Users\glukhov\.m2\repository\org\seleniumhq\selenium\selenium-support\3.12.0\selenium-support-3.12.0.jar;C:\Users\glukhov\.m2\repository\net\bytebuddy\byte-buddy\1.8.3\byte-buddy-1.8.3.jar;C:\Users\glukhov\.m2\repository\org\testng\testng\6.14.3\testng-6.14.3.jar;C:\Users\glukhov\.m2\repository\org\springframework\spring-context\5.0.6.RELEASE\spring-context-5.0.6.RELEASE.jar;C:\Users\glukhov\.m2\repository\org\springframework\spring-aop\5.0.6.RELEASE\spring-aop-5.0.6.RELEASE.jar;C:\Users\glukhov\.m2\repository\org\springframework\spring-beans\5.0.6.RELEASE\spring-beans-5.0.6.RELEASE.jar;C:\Users\glukhov\.m2\repository\org\springframework\spring-core\5.0.6.RELEASE\spring-core-5.0.6.RELEASE.jar;C:\Users\glukhov\.m2\repository\org\springframework\spring-jcl\5.0.6.RELEASE\spring-jcl-5.0.6.RELEASE.jar;C:\Users\glukhov\.m2\repository\org\springframework\spring-expression\5.0.6.RELEASE\spring-expression-5.0.6.RELEASE.jar;C:\Users\glukhov\.m2\repository\org\springframework\spring-tx\5.0.6.RELEASE\spring-tx-5.0.6.RELEASE.jar;C:\Users\glukhov\.m2\repository\org\springframework\spring-test\5.0.6.RELEASE\spring-test-5.0.6.RELEASE.jar;C:\Users\glukhov\.m2\repository\org\springframework\spring-jdbc\5.0.6.RELEASE\spring-jdbc-5.0.6.RELEASE.jar;C:\Users\glukhov\.m2\repository\com\fasterxml\jackson\core\jackson-databind\2.9.5\jackson-databind-2.9.5.jar;C:\Users\glukhov\.m2\repository\com\fasterxml\jackson\core\jackson-annotations\2.9.0\jackson-annotations-2.9.0.jar;C:\Users\glukhov\.m2\repository\com\fasterxml\jackson\core\jackson-core\2.9.5\jackson-core-2.9.5.jar;C:\Users\glukhov\.m2\repository\com\fasterxml\jackson\dataformat\jackson-dataformat-yaml\2.9.5\jackson-dataformat-yaml-2.9.5.jar;C:\Users\glukhov\.m2\repository\org\yaml\snakeyaml\1.18\snakeyaml-1.18.jar;C:\Users\glukhov\.m2\repository\org\apache\logging\log4j\log4j-jcl\2.11.0\log4j-jcl-2.11.0.jar;C:\Users\glukhov\.m2\repository\org\apache\logging\log4j\log4j-api\2.11.0\log4j-api-2.11.0.jar;C:\Users\glukhov\.m2\repository\org\apache\logging\log4j\log4j-core\2.11.0\log4j-core-2.11.0.jar;C:\Users\glukhov\.m2\repository\org\apache\commons\commons-lang3\3.4\commons-lang3-3.4.jar;C:\Users\glukhov\.m2\repository\org\apache\commons\commons-exec\1.3\commons-exec-1.3.jar;C:\Users\glukhov\.m2\repository\commons-codec\commons-codec\1.10\commons-codec-1.10.jar;C:\Users\glukhov\.m2\repository\commons-logging\commons-logging\1.2\commons-logging-1.2.jar;C:\Users\glukhov\.m2\repository\com\google\code\gson\gson\2.8.2\gson-2.8.2.jar;C:\Users\glukhov\.m2\repository\com\google\guava\guava\23.6-jre\guava-23.6-jre.jar;C:\Users\glukhov\.m2\repository\com\google\code\findbugs\jsr305\1.3.9\jsr305-1.3.9.jar;C:\Users\glukhov\.m2\repository\org\checkerframework\checker-compat-qual\2.0.0\checker-compat-qual-2.0.0.jar;C:\Users\glukhov\.m2\repository\com\google\errorprone\error_prone_annotations\2.1.3\error_prone_annotations-2.1.3.jar;C:\Users\glukhov\.m2\repository\com\google\j2objc\j2objc-annotations\1.1\j2objc-annotations-1.1.jar;C:\Users\glukhov\.m2\repository\org\codehaus\mojo\animal-sniffer-annotations\1.14\animal-sniffer-annotations-1.14.jar;C:\Users\glukhov\.m2\repository\org\apache\httpcomponents\httpclient\4.5.3\httpclient-4.5.3.jar;C:\Users\glukhov\.m2\repository\org\apache\httpcomponents\httpcore\4.4.6\httpcore-4.4.6.jar;C:\Users\glukhov\.m2\repository\com\squareup\okhttp3\okhttp\3.9.1\okhttp-3.9.1.jar;C:\Users\glukhov\.m2\repository\com\squareup\okio\okio\1.13.0\okio-1.13.0.jar;C:\Users\glukhov\.m2\repository\mysql\mysql-connector-java\5.1.46\mysql-connector-java-5.1.46.jar;C:\Users\glukhov\.m2\repository\com\beust\jcommander\1.72\jcommander-1.72.jar;C:\Users\glukhov\.m2\repository\org\apache-extras\beanshell\bsh\2.0b6\bsh-2.0b6.jar;C:\Users\glukhov\.m2\repository\com\alibaba\fastjson\1.2.33\fastjson-1.2.33.jar;C:\Users\glukhov\.m2\repository\org\mybatis\mybatis-spring\1.3.2\mybatis-spring-1.3.2.jar;C:\Users\glukhov\.m2\repository\org\mybatis\mybatis\3.4.6\mybatis-3.4.6.jar;C:\Users\glukhov\.m2\repository\org\aspectj\aspectjweaver\1.8.13\aspectjweaver-1.8.13.jar;C:\Program
Files\JetBrains\IntelliJ IDEA
2018.1\plugins\testng\lib\jcommander.jar"
org.testng.RemoteTestNGStarter -usedefaultlisteners false -socket53035
@w@C:\Users\glukhov\AppData\Local\Temp2\idea_working_dirs_testng.tmp
-temp C:\Users\glukhov\AppData\Local\Temp2\idea_testng.tmp
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by
org.springframework.cglib.core.ReflectUtils$1
(file:/C:/Users/glukhov/.m2/repository/org/springframework/spring-core/5.0.6.RELEASE/spring-core-5.0.6.RELEASE.jar)
to method java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)
WARNING: Please consider reporting this to the maintainers of
org.springframework.cglib.core.ReflectUtils$1
WARNING: Use --illegal-access=warn to enable warnings of further
illegal reflective access operations
WARNING: All illegal access operations will be denied in a future
releaseStarting ChromeDriver 2.38.552522
(437e6fbedfa8762dec75e2c5b3ddb86763dc9dcb) on port 3968Only local
connections are allowed.июн. 07, 2018 5:15:40 ПП
org.openqa.selenium.remote.ProtocolHandshake createSession
INFO: Detected dialect: OSS2018-06-07 17:15:41,448 INFO  - Создаём
заказ под Грибановым и отправляем менеджеру на согласование2018-06-07
17:16:28,646 INFO  - Авторизуемся под менеджером (Новосельцев)
и
отклоняем заказ2018-06-07 17:16:40,269 INFO  - Авторизуемся под
Грибановым, вводим описание проблемы, отправляем
менеджеру на
согласование2018-06-07 17:17:18,522 INFO  - Авторизуемся под
мендежером (Новосельцев) и согласовываем2018-06-07 17:17:28,654
INFO
- Авторизуемся под Верещагиным и отклоняем2018-06-07 17:17:40,732
INFO
 - Авторизуемся под Грибановым
===============================================Default SuiteTotal
tests run: 2, Failures: 0, Skips:
0===============================================

Process finished with exit code 0

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message