Dummy debug log '[Graph] ......' is in console log

[bobshie]

TestNG Version

7.6.1

Expected behavior

No so much dummy logs

Actual behavior

There is a lot of [Graph] debug info in console log.

        13:48:07.930 [main] DEBUG org.testng.TestNG - suiteXmlPath: "temp-testng-customsuite.xml"
        13:48:08.392 [main] DEBUG org.testng.internal.Graph - [Graph] ADDING NODE TestNGTest.testTestLog()[pri:0, instance:TestNGTest@7ef27d7f] -148949384
        13:48:08.392 [main] DEBUG org.testng.internal.Graph - [Graph] ================ SORTING
        13:48:08.397 [main] DEBUG org.testng.internal.Graph - [Graph] =============== DONE SORTING
        13:48:08.398 [main] DEBUG org.testng.internal.Graph - [Graph] ====== SORTED NODES
        13:48:08.398 [main] DEBUG org.testng.internal.Graph - [Graph] ====== END SORTED NODES
        13:48:08.409 [main] INFO  org.testng.internal.Utils - [TestNG] Running:
          temp-testng-customsuite.xml
        
        13:48:08.525 [main] INFO  TestNGTest - Start test
        13:48:09.538 [main] INFO  TestNGTest - Stop test

Is the issue reproducible on runner?

• Shell
• Maven
• Gradle
• Ant
• Eclipse
• IntelliJ
• NetBeans

Test case sample

    @Test
    public void testTestLog() {
        logger.info("Start test");
        sleep(1);
        logger.info("Stop test");
    }

Related change

the code is in:
https://github.com/cbeust/testng/blame/master/testng-core/src/main/java/org/testng/internal/Graph.java

the related change:
f03a6f6
krmahadevan committed on Jun 12, 2021 7.6.1
Renamed the ppp methods to debug/log in production code.

  System.out.println("[Graph] " + s.get());
  Logger.getLogger(Graph.class).debug("[Graph] " + s.get());
  
  m_verbose = false

e72bf13#diff-f0ae988831fcbad2a15319deb0f81dbd7756516211db7d78284ff2088d230f5b
krmahadevan committed on Dec 31, 2021 7.6.1

in this change, m_verbose is changed to true, so there are a lot of dummy debug information in console log.

Suggestion

It's better to use Environment Variable to console the m_verbose flag. m_verbose should be false by default.

[krmahadevan]

@bobshie

in this change, m_verbose is changed to true, so there are a lot of dummy debug information in console log.

Why not raise a PR wherein you add the proposed suggestion ?

[bobshie]

@krmahadevan , thanks for your quickly answer.
I didn't do PR before, I'll try it later.

[juherr]

Fixed by #2813

[bobshie]

Hello, I verify the latest version of testng,
there are still a lot of logs:

left is testng 7.6.1
right is testng 7.6.2-SNAPSHOT version.

and I checked the change: #2813

the verbose=true is remove, but log("") function keeps....
I think nothing is change?

[krmahadevan]

@bobshie - There can be two reasons why you are seeing this behaviour.

1. You are working with a SNAPSHOT jar that doesn't still have the changes. Can you please check the jar and ensure that you have these changes in your local jar ? https://github.com/cbeust/testng/blob/133ac2827c04c0464546beb015b6f2e5b72d5023/testng-core/src/main/java/org/testng/internal/Graph.java#L167-L173
2. Check if you are having an slf4j log configuration file in your CLASSPATH (log4j.properties or a logback.xml maybe?)

Please post back your findings.

[bobshie]

Hello @krmahadevan, I pull the latest code and compile the code locally. I checked the code, it use log4j to print the information.

If i don't want these debug information, I need to disable the Graph logger level in log4j config file.

can we lower this log level?

 Logger.getLogger(Graph.class).trace("[Graph] " + s.get()); 

[bobshie]

We have a lot of test cases and CI flows that based on TestNG, it's hard to change the log4j config file one by one to disable the org.testng.internal.Graph log level.

[krmahadevan]

Hello @krmahadevan, I pull the latest code and compile the code locally. I checked the code, it use log4j to print the information.

If i don't want these debug information, I need to disable the Graph logger level in log4j config file.

can we lower this log level?

 Logger.getLogger(Graph.class).trace("[Graph] " + s.get()); 

Why would adding a logger config to turn this logger off in your log4j properties file not work here ? Can you please let us know? Trying to understand the rationale here.

[bobshie]

The code is OK, That's no problem.

if I add logger config and turn this logger off, it works, like:.

   <Loggers>
	<Logger name="org.testng.internal.Graph" level="INFO" />
	<Root level="DEBUG">
		<AppenderRef ref="Console" />
	</Root>
</Loggers>

but we need to add "" in all CI flows to disable this debug information log.

Mostly 'DEBUG' is default level of ROOT for troubleshooting of test cases and other libraries.

if '[Graph]' is just used to debug TestNG issue and TestNG's stable , so we can change these debug information log to TRACE level.

[krmahadevan]

@bobshie - Just curious. If you saw debug statements originating from other libraries, what would you strategy be? Irrespective of the rationale behind why TestNG does this debug level logging on Graph class, I believe that its done at debug level for a reason (To debug in case of problems).

Am sure that you would agree as well, that your logger configuration file is at fault here and it should have set the logger levels for your test code packages to debug rather than setting the root level to debug and expecting all dependencies to alter their code to suite the test needs no ?

[bobshie]

hi @krmahadevan, I think it's history issue that config of most projects set DEBUG level on ROOT. and our test cases of most projects are very complex and include a lot of common libraries, it's hard to enable debug level for many classes.
usually, we will disable some dummy logs in log4j config file, such as:

    <Logger name="org.apache.http.headers" level="INFO" />
    <Logger name="org.apache.http.wire" level="INFO" />
    <Logger name="org.opendaylight.yangtools.yang.parser" level="OFF" />
    <Logger name="org.opendaylight.yangtools.util" level="OFF" />

the number of these class is not so much, so we can do it one by one.

if TestNG has such log from beginning, we can also disable it like that. but, these logs is introduced after 7.6.1, so we need to change a lot of log4j configuration file.

The other think, when we run unit test with TestNG, these will be a lot of TestNG Graph logs in console:

Standard Output
[1] 2022-11-14T10:53:44,945 DEBUG  [Graph] ADDING NODE CustomVerifyTest.init()[pri:0, instance:null] 844833384
[1] 2022-11-14T10:53:44,946 DEBUG  [Graph]   ADDING PREDECESSOR FOR CustomVerifyTest.init()[pri:0, instance:null] ==> AbcTestBase.beforeClass()[pri:0, instance:null]
[1] 2022-11-14T10:53:44,947 DEBUG  [Graph]   REMOVED AbcTestBase.beforeClass()[pri:0, instance:null] FROM INDEPENDENT OBJECTS
[1] 2022-11-14T10:53:44,947 DEBUG  [Graph] ADDING NODE AbcTestBase.beforeClass()[pri:0, instance:null] 1194269361
[1] 2022-11-14T10:53:44,947 DEBUG  [Graph] ================ SORTING
[1] 2022-11-14T10:53:44,947 DEBUG  [Graph]   ADDING PREDECESSOR FOR CustomVerifyTest.init()[pri:0, instance:null] ==> AbcTestBase.beforeClass()[pri:0, instance:null]
[1] 2022-11-14T10:53:44,948 DEBUG  [Graph]   REMOVED PRED AbcTestBase.beforeClass()[pri:0, instance:null] FROM NODE CustomVerifyTest.init()[pri:0, instance:null]
[1] 2022-11-14T10:53:44,948 DEBUG  [Graph] =============== DONE SORTING
[1] 2022-11-14T10:53:44,948 DEBUG  [Graph] ====== SORTED NODES
[1] 2022-11-14T10:53:44,948 DEBUG  [Graph]               AbcTestBase.beforeClass()[pri:0, instance:null]
[1] 2022-11-14T10:53:44,948 DEBUG  [Graph]               CustomVerifyTest.init()[pri:0, instance:null]
[1] 2022-11-14T10:53:44,948 DEBUG  [Graph] ====== END SORTED NODES
[1] 2022-11-14T10:53:44,951 DEBUG  [Graph] ADDING NODE CustomTest.testFailedDualWithCustomVerdictLevel()[pri:0, instance:com.xxx.demo.CustomTest@5cc5c7ac] -954326119
[1] 2022-11-14T10:53:44,951 DEBUG  [Graph] ADDING NODE CustomTest.testFailedWithCustomVerdictLevel()[pri:0, instance:com.xxx.demo.CustomTest@5cc5c7ac] -1158337339
[1] 2022-11-14T10:53:44,951 DEBUG  [Graph] ADDING NODE CustomTest.testSuccessful()[pri:0, instance:com.xxx.demo.CustomTest@5cc5c7ac] 1015562872
[1] 2022-11-14T10:53:44,951 DEBUG  [Graph] ADDING NODE CustomTest.verifyDualSuccessful()[pri:0, instance:com.xxx.demo.CustomTest@5cc5c7ac] 471527383
[1] 2022-11-14T10:53:44,951 DEBUG  [Graph] ================ SORTING
[1] 2022-11-14T10:53:44,953 DEBUG  [Graph] =============== DONE SORTING
[1] 2022-11-14T10:53:44,953 DEBUG  [Graph] ====== SORTED NODES
[1] 2022-11-14T10:53:44,953 DEBUG  [Graph] ====== END SORTED NODES

So it's better to lower the log level.

[krmahadevan]

@bobshie - I dont agree with the rationale of history. As you move forward with versions of libraries, there can be changes in log levels of libraries and we cannot expect libraries to accommodate our expectations of their log levels.

Log levels being verbose at DEBUG levels IMO is expected and is something that many libraries across the industry follow/employ. If verbose logs were being output at INFO level I can understand it being an inconvenience but not sure why debug logs would be of inconvenience here especially when there is a simple straight forward way of disabling them. You just need to set the log level of org.testng to INFO or above and this should go away.

something like this

<Logger name="org.testng" level="INFO" />

Why is TestNG expected to accommodate this change is what I fail to understand. Today you would like the debug log level be changed in one place, tomorrow someone else would have a problem somewhere else. So my concern here is NOT on the nature of the change (Yes I know its a trivial change) but the intent of the change.

The logs being verbose for TestNG tests can be fixed by adding a test level logger. But I dont see any issue with debug logs being printed when unit tests are being run.

[bobshie]

I'm not sure why TestNG add such logs in Debug Level, It's too detail for TestNG users. and if we want to disable such logs, we need to add in many places for all test cases that based on TestNG.

org.opendaylight and org.apache.http doesn't has such issue for just some of test cases use it.

We don't want to disable all debug logs for TestNG, like that

So, we can't easy to change all log4j files in CI flow.

 "But I dont see any issue with debug logs being printed when unit tests are being run."

OK, the problem is that after I uplift TestNG, there are a lot of dummy TestNG logs in console log and there are the similar in out unit tests and system tests and many person complaint it.

We need to think how to resolve it if TestNG don't want to change it.

[martinaldrin]

Hi @krmahadevan

Our Project have about 500 Git projects, Default Log level is DEBUG, which means that we will need to update 500 log4j2.xml files to exclude this Graph logging for unit test only. But that is not the worst, and on top of that we have our production code that also run TestNg tests cases that also needs to be updates, which are owned by other teams.

In my view this sorting does not give any value to the end user, mainly used for TestNg developers. And therefor I think the log level debug is too low, We normally put logs that are not valuable for our end users or if they spam too much at TRACE level.

The problem with log4j2 configurations is that we can not update it in a central place, we need to updated in so many projects and as Bob say we have similar issues with other 3pp projects as well, but non of them are so wildly used as TestNg

I hope you understand our problem and can solve this in one or another way.

Thanks
/Martin

[krmahadevan]

@bobshie @martinaldrin - Graph logs at trace level is now available master branch.

[bobshie]

hello @krmahadevan , Very thanks for your understanding, I'll get the latest snapshot to verify it.