Use more human-readable appender format for STs logs

[Frawless]

Type of change

• Enhancement / new feature

Description

This PR change the format of console and rolling appender for system tests to make it more human readable. It adds info which test class and test method calls the log:

2025-04-23 07:21:55 [T-92] [UserST] INFO  [DeploymentUtils:180] Waiting for 1 Pod(s) of Deployment: test-suite-namespace/cluster-2ac2af89-scraper to be ready
2025-04-23 07:21:55 [T-92] [UserST] INFO  [DeploymentUtils:183] Deployment: test-suite-namespace/cluster-2ac2af89-scraper is ready
2025-04-23 07:21:55 [T-92] [UserST] INFO  [TestSeparator:37] ############################################################################
2025-04-23 07:21:55 [T-97]  INFO  [TestSeparator:37] ############################################################################
2025-04-23 07:21:55 [T-92] [UserST] INFO  [TestSeparator:38] io.strimzi.systemtest.operators.user.UserST.testCreatingUsersWithSecretPrefix-STARTED
2025-04-23 07:21:55 [T-97]  INFO  [TestSeparator:38] io.strimzi.systemtest.operators.user.UserST.testTlsExternalUserWithQuotas-STARTED
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [AbstractST:106] Not first test we are gonna generate cluster name
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [TestSuiteNamespaceManager:96] Creating Namespace: namespace-0 for TestCase: testCreatingUsersWithSecretPrefix
2025-04-23 07:21:55 [T-172]  INFO  [TestSeparator:37] ############################################################################
2025-04-23 07:21:55 [T-172]  INFO  [TestSeparator:38] io.strimzi.systemtest.operators.user.UserST.testUpdateUser-STARTED
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [NamespaceManager:106] Creating Namespace: namespace-0
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [ResourceManager:260] Setting Namespace: namespace-0 to resource: NetworkPolicy/global-network-policy
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [ResourceManager:600] Creating/Updating NetworkPolicy namespace-0/global-network-policy
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [NetworkPolicyResource:287] NetworkPolicy successfully set to: true for Namespace: namespace-0
2025-04-23 07:21:55 [T-97] [UserST][testTlsExternalUserWithQuotas] INFO  [AbstractST:106] Not first test we are gonna generate cluster name
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [ResourceManager:260] Setting Namespace: namespace-0 to resource: KafkaNodePool/b-7efe740b
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [ResourceManager:600] Creating/Updating KafkaNodePool namespace-0/b-7efe740b
2025-04-23 07:21:55 [T-97] [UserST][testTlsExternalUserWithQuotas] INFO  [ResourceManager:600] Creating/Updating KafkaUser test-suite-namespace/my-user-1295152100-507152825
2025-04-23 07:21:55 [T-175]  INFO  [TestSeparator:37] ############################################################################
2025-04-23 07:21:55 [T-175]  INFO  [TestSeparator:38] io.strimzi.systemtest.operators.user.UserST.testTlsExternalUser-STARTED
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [ResourceManager:260] Setting Namespace: namespace-0 to resource: KafkaNodePool/c-7efe740b
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [ResourceManager:600] Creating/Updating KafkaNodePool namespace-0/c-7efe740b
2025-04-23 07:21:55 [T-97] [UserST][testTlsExternalUserWithQuotas] INFO  [ResourceManager:493] Waiting for KafkaUser: test-suite-namespace/my-user-1295152100-507152825 will have desired state: Ready
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [ResourceManager:260] Setting Namespace: namespace-0 to resource: Kafka/cluster-56d6ccde
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [ResourceManager:600] Creating/Updating Kafka namespace-0/cluster-56d6ccde
2025-04-23 07:21:55 [T-92] [UserST][testCreatingUsersWithSecretPrefix] INFO  [ResourceManager:493] Waiting for Kafka: namespace-0/cluster-56d6ccde will have desired state: Ready
2025-04-23 07:21:56 [T-97] [UserST][testTlsExternalUserWithQuotas] INFO  [ResourceManager:504] KafkaUser: test-suite-namespace/my-user-1295152100-507152825 is in desired state: Ready
2025-04-23 07:21:58 [T-97] [UserST][testTlsExternalUserWithQuotas] INFO  [Exec:451] Command: 'kubectl --namespace test-suite-namespace exec cluster-2ac2af89-scraper-65d5c89dc9-2fr8x -- /bin/bash -c bin/kafka-configs.sh --bootstrap-server cluster-2ac2af89-kafka-bootstrap:9092 --entity-type users --entity-name CN=my-user-1295152100-507152825 --describe' (return code: 0)
2025-04-23 07:21:58 [T-97] [UserST][testTlsExternalUserWithQuotas] INFO  [KafkaClients:98] Consumer group were not specified going to create the random one
2025-04-23 07:21:58 [T-97] [UserST][testTlsExternalUserWithQuotas] INFO  [OpenSsl:121] Creating client RSA private key with size of 2048 bits
2025-04-23 07:21:58 [T-97] [UserST][testTlsExternalUserWithQuotas] INFO  [OpenSsl:138] Creating Certificate Signing Request file
2025-04-23 07:21:58 [T-97] [UserST][testTlsExternalUserWithQuotas] INFO  [OpenSsl:156] Creating signed certificate file
2025-04-23 07:22:08 [T-97] [UserST][testTlsExternalUserWithQuotas] INFO  [SecretUtils:48] Waiting for Secret: test-suite-namespace/my-user-1295152100-507152825 to exist
2025-04-23 07:22:08 [T-97] [UserST][testTlsExternalUserWithQuotas] INFO  [SecretUtils:52] Secret: test-suite-namespace/my-user-1295152100-507152825 created

it also shrink the thread log format from whole name into T-<THREAD_ID>

Rolling appender: https://artifacts.dev.testing-farm.io/3c2b0297-55b0-4715-8c57-b9ec2fd801a7/work-regression-operatorseb5qos8_/systemtest/tmt/plans/regression-operators/data/logs/logs/strimzi-debug-0.log
Console appender: https://artifacts.dev.testing-farm.io/3c2b0297-55b0-4715-8c57-b9ec2fd801a7/

Checklist

• Make sure all tests pass

[Frawless]

/packit test --labels regression

[Frawless]

No strong opinion, but maybe it will b better to put log level right after timestamp or thread ID.

[kornys]

makes sense to me

[im-konge]

I like how clear it is from what test the particular log is. On the other hand, I don't know if it should be that long. I mean, it will create half of screen with info about log level, thread, test class, test itself and timestamp. I know that maybe we can't do much, but having it a bit shorter would help I guess.

[Frawless]

I like how clear it is from what test the particular log is. On the other hand, I don't know if it should be that long. I mean, it will create half of screen with info about log level, thread, test class, test itself and timestamp. I know that maybe we can't do much, but having it a bit shorter would help I guess.

I can conditionally set testClass and testMethod properties for MDC based on parallel test execution config which won't extend the log for azure for example, but that's all. I am not sure how to make it "shorter" than this (if you have any idea I am listening).

From my POV the log is much more readable when running regression on TF for example as thread ID is not enough to properly filter things. Maybe another option would be to simply replace the appender config in certain situations (when junit.jupiter.execution.parallel.enabled=true for example) instead of conditionally set the properties for MDC.

[im-konge]

I didn't mean it like it's not clear. Just that it's long FMPOV. I was thinking if just the test case name would be enough or not 🤔 Because in case of NamespaceRbacScopeOperatorST#testNamespacedRbacScopeDeploysRoles for example it will be really a long line (or AlternativeReconcileTriggersST#testTriggerRollingUpdateAfterOverrideBootstrap).

[Frawless]

I didn't mean it like it's not clear. Just that it's long FMPOV. I was thinking if just the test case name would be enough or not 🤔 Because in case of NamespaceRbacScopeOperatorST#testNamespacedRbacScopeDeploysRoles for example it will be really a long line (or AlternativeReconcileTriggersST#testTriggerRollingUpdateAfterOverrideBootstrap).

I know, I feel it in the same way, but everytime I open logs from parallel executions it is really pain. I would stick with with strings is there might be tests with same name, but in general the class name could be removed I think as we do not support test class parallelism.

[im-konge]

I didn't mean it like it's not clear. Just that it's long FMPOV. I was thinking if just the test case name would be enough or not 🤔 Because in case of NamespaceRbacScopeOperatorST#testNamespacedRbacScopeDeploysRoles for example it will be really a long line (or AlternativeReconcileTriggersST#testTriggerRollingUpdateAfterOverrideBootstrap).

I know, I feel it in the same way, but everytime I open logs from parallel executions it is really pain. I would stick with with strings is there might be tests with same name, but in general the class name could be removed I think as we do not support test class parallelism.

Yeah I feel the same way, debugging stuff with the parallel execution stuff is really pain. Look, if you want to keep it as it is, I'm fine with that. If you will remove the class name (as you mentioned, we don't have class-wide parallelism) I'm fine with that as well. I just wanted to point that it could be really long line if we keep both.

[Frawless]

/packit test --labels regression

[im-konge]

LGTM, thanks

[Frawless]

/packit test --labels regression

[Frawless]

/azp run acceptance

[azure-pipelines]

Azure Pipelines successfully started running 1 pipeline(s).

[Frawless]

It seems that failed TF jobs were just triggered by some outage. THe followup regression run is fine. Also Azure logs seems to be good. @see-quick any comments or I can merge it once it will finish?

[see-quick]

LGTM, thanks 👍