Build going into inifinite loop on running `mvn oc:build -Dorg.slf4j.simpleLogger.defaultLogLevel=trace`` #1950

rohanKanojia · 2022-11-30T06:34:27Z

Describe the bug

When trying to use KubernetesClient verbose logs, using org.slf4j.simpleLogger.defaultLogLevel=trace property, I'm seeing build goes into an infinite loop in OpenShift Maven Plugin oc:build goal. This seems to be happening during the OpenShift S2I build when BuildConfig is submitted to OpenShift APIServer.

Meanwhile, the Build Pod never seems to come out of this stage:

 $ oc get pods
NAME                           READY     STATUS     RESTARTS   AGE
random-generator-s2i-3-build   0/1       Init:0/2   0          6m29s

Eclipse JKube version

1.10.0

Component

OpenShift Maven Plugin

Apache Maven version

3.8.5

Gradle version

No response

Steps to reproduce

Run mvn oc:build -Dorg.slf4j.simpleLogger.defaultLogLevel=trace in your project in presence of an OpenShift Cluster.

Expected behavior

Build should succeed within 1-2 minutes with verbose logs

Runtime

OpenShift

Kubernetes API Server version

1.24.7

Environment

Linux

Eclipse JKube Logs

NFO: --> POST https://api.sandbox.example.com:6443/apis/build.openshift.io/v1/namespaces/rokumar-dev/buildconfigs/random-generator-s2i/instantiatebinary?name=random-generator-s2i&namespace=rokumar-dev h2
^CNov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Content-Type: application/octet-stream
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Content-Length: 21053952
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Expect: 100-continue
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Authorization: Bearer sha256~_NMvkcN6PqDi9ZaOw02_8NYOZj490UIG-UiRnmyGlNE
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: User-Agent: fabric8-kubernetes-client/6.1.1
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Host: api.sandbox.example.com:6443
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Connection: Keep-Alive
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Accept-Encoding: gzip
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: --> POST https://api.sandbox.example.com:6443/apis/build.openshift.io/v1/namespaces/rokumar-dev/buildconfigs/random-generator-s2i/instantiatebinary?name=random-generator-s2i&namespace=rokumar-dev h2
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Content-Type: application/octet-stream
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Content-Length: 21053952
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Expect: 100-continue
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Authorization: Bearer sha256~_NMvkcN6PqDi9ZaOw02_8NYOZj490UIG-UiRnmyGlNE
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: User-Agent: fabric8-kubernetes-client/6.1.1
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Host: api.sandbox.example.com:6443
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Connection: Keep-Alive
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Accept-Encoding: gzip
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: --> POST https://api.sandbox.example.com:6443/apis/build.openshift.io/v1/namespaces/rokumar-dev/buildconfigs/random-generator-s2i/instantiatebinary?name=random-generator-s2i&namespace=rokumar-dev h2
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Content-Type: application/octet-stream
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Content-Length: 21053952
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Expect: 100-continue
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Authorization: Bearer sha256~_NMvkcN6PqDi9ZaOw02_8NYOZj490UIG-UiRnmyGlNE
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: User-Agent: fabric8-kubernetes-client/6.1.1
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Host: api.sandbox.example.com:6443
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Connection: Keep-Alive
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: Accept-Encoding: gzip
Nov 30, 2022 11:46:31 AM okhttp3.internal.platform.Platform log
INFO: --> POST https://api.sandbox.example.com:6443/apis/build.openshift.io/v1/namespaces/rokumar-dev/buildconfigs/random-generator-s2i/instantiatebinary?name=random-generator-s2i&namespace=rokumar-dev h2

Sample Reproducer Project

No response

Additional context

No response

The text was updated successfully, but these errors were encountered:

DhirajSardar · 2022-12-02T15:34:23Z

Can You point me to some of resources so that I can contribute ?

rohanKanojia · 2022-12-02T15:48:47Z

@DhirajSardar : Sorry, but this is not a good issue for newcomers. I would advise you to look into currently open issues with label help wanted, good first issue .

DhirajSardar · 2022-12-03T13:45:29Z

Thank you for reaching out to me.Can you guide me to make my first contribution ?

…

On Fri, 2 Dec 2022 at 21:18, Rohan Kumar ***@***.***> wrote: @DhirajSardar <https://github.com/DhirajSardar> : Sorry, but this is not a good issue for newcomers. I would advise you to look into currently open issues with label help wanted, good first issue . — Reply to this email directly, view it on GitHub <#1950 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AWZXMBES2MXG4VK266VKK3DWLIK6XANCNFSM6AAAAAASPIVQ6E> . You are receiving this because you were mentioned.Message ID: ***@***.***>

rohanKanojia · 2022-12-05T06:04:02Z

@DhirajSardar : I've written a blogpost on this topic: https://rohaan.medium.com/how-to-contribute-to-eclipse-jkube-f3bc7f902bf4 . Could you please give it a read and see if it helps?

rohanKanojia · 2023-01-18T05:47:22Z

I think there is some problem with instantiating BuildConfig during oc:build in trace log:

We try to upload file to OpenShift API server:

https://github.com/eclipse/jkube/blob/174d1897655b8af31637d79728169768d2cf8004/jkube-kit/config/service/src/main/java/org/eclipse/jkube/kit/config/service/openshift/OpenshiftBuildService.java#L443-L445

but control is never returned. Checking BuildConfigOperationsImpl, it seems to be stuck waiting for response; future never seems to be getting satisfied.

manusa · 2023-01-18T06:15:00Z

This seems to be completely related to #2000

The following snippet is evaluated when the generic trace option is enabled:
https://github.com/fabric8io/kubernetes-client/blob/0b1e79660e8c59a2a0def7f7593bae8d2b02282b/httpclient-okhttp/src/main/java/io/fabric8/kubernetes/client/okhttp/OkHttpClientFactory.java#L75-L80

Since the bodies of the request and response are printed and cannot be reset, everything else fails.

We need to specifically disable tracing for that logger, or at least set the level to BASIC instead.

rohanKanojia · 2023-01-18T06:17:04Z

@manusa : Is it possible to disable this logger for a class (BuildConfigOperationsImpl)?

manusa · 2023-01-18T06:20:07Z

It depends on the logger implementation, but it should be possible. In any case, I think that the logger that should be disabled is the one related to okhttp3.logging.HttpLoggingInterceptor.

-Dorg.slf4j.simpleLogger.log.okhttp3.logging.HttpLoggingInterceptor=BASIC or -Dorg.slf4j.simpleLogger.log.okhttp3.logging.HttpLoggingInterceptor=off might get the job done, but haven't tried it.

References:

https://www.slf4j.org/api/org/slf4j/simple/SimpleLogger.html

rohanKanojia · 2023-01-18T06:25:12Z

Thanks, I just tried it and oc:build seems to work as expected

mvn oc:build -Dorg.slf4j.simpleLogger.log.okhttp3.logging.HttpLoggingInterceptor=off -Dorg.slf4j.simpleLogger.defaultLogLevel=trace  -Djkube.version=1.10.1

This works as well:

mvn oc:build -Dorg.slf4j.simpleLogger.log.okhttp3.logging.HttpLoggingInterceptor=BASIC -Dorg.slf4j.simpleLogger.defaultLogLevel=trace  -Djkube.version=1.10.1

rohanKanojia · 2023-01-18T08:14:21Z

I also tried by hardcoding HttpLoggingInterceptor's level to BASIC in KubernetesClient and using 6.4-SNAPSHOT in jkube. This also seems to resolve this issue.

Should we make this change in KubernetesClient? Or shall we just add documentation/FAQ for this?

manusa · 2023-01-18T09:08:56Z

I also tried by hardcoding HttpLoggingInterceptor's level to BASIC in KubernetesClient and using 6.4-SNAPSHOT in jkube. This also seems to resolve this issue.

Should we make this change in KubernetesClient? Or shall we just add documentation/FAQ for this?

I'm not sure I'm following here.
The problem is that we conditionally add the HttpLoginInterceptor in the client in case it's level is set to TRACE (see the linked code in my previous response).
The only thing we can do from JKube is see if we can override this lever for this specific class in all cases, however, I'm not sure this is possible.

…ems with KubernetesClient (eclipse-jkube#1950) Add a workaround to forcefully set `org.slf4j.simpleLogger.log.okhttp3.logging.HttpLoggingInterceptor` property to `BASIC` to prevent OkHttp's HttpLoggingInterceptor to interfere with KubernetesClient operations. Signed-off-by: Rohan Kumar <rohaan@redhat.com>

rohanKanojia added the bug Something isn't working label Nov 30, 2022

rohanKanojia added this to Eclipse JKube Dec 13, 2022

manusa moved this to Planned in Eclipse JKube Jan 4, 2023

rohanKanojia self-assigned this Jan 12, 2023

manusa mentioned this issue Jan 13, 2023

Build fails with "-Dorg.slf4j.simpleLogger.defaultLogLevel=trace" option #2000

Closed

rohanKanojia moved this from Planned to In Progress in Eclipse JKube Jan 17, 2023

rohanKanojia mentioned this issue Jan 18, 2023

fix (jkube-kit/config) : Add workaround for trace level logging problems with KubernetesClient (#1950) #2006

Closed

17 tasks

rohanKanojia moved this from In Progress to Review in Eclipse JKube Jan 18, 2023

manusa unassigned rohanKanojia Jan 23, 2023

manusa moved this from Review to Planned in Eclipse JKube Jan 23, 2023

This was referenced Mar 27, 2023

gradle task for k8sRemoteDev starts and finishes without any error #2075

Closed

feat: additional callback methods for Interceptor interface fabric8io/kubernetes-client#5025

Merged

manusa mentioned this issue Apr 6, 2023

feat: generic HttpLoggingInterceptor fabric8io/kubernetes-client#5037

Merged

11 tasks

manusa self-assigned this May 3, 2023

manusa moved this from Planned to In Progress in Eclipse JKube May 3, 2023

manusa mentioned this issue May 4, 2023

deps: fix: bump Kubernetes Client to 6.6.0 (fixes issues when trace-logging OpenShift builds) #2150

Merged

17 tasks

manusa moved this from In Progress to Review in Eclipse JKube May 4, 2023

manusa added this to the 1.13.0 milestone May 5, 2023

manusa closed this as completed in #2150 May 8, 2023

github-project-automation bot moved this from Review to Done in Eclipse JKube May 8, 2023

manusa mentioned this issue Jun 5, 2023

[Internal]: Kubernetes HTTP API request/response logging #2193

Closed

This was referenced Jun 15, 2023

Create test to ensure HttpLoggingInterceptor doesn't consume bytes fabric8io/kubernetes-client#5251

Closed

Create E2E test to verify that OpenShiftBuilds (and other operations) can be logged #2211

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Build going into inifinite loop on running `mvn oc:build -Dorg.slf4j.simpleLogger.defaultLogLevel=trace`` #1950

Build going into inifinite loop on running `mvn oc:build -Dorg.slf4j.simpleLogger.defaultLogLevel=trace`` #1950

rohanKanojia commented Nov 30, 2022 •

edited

Loading

DhirajSardar commented Dec 2, 2022

rohanKanojia commented Dec 2, 2022

DhirajSardar commented Dec 3, 2022 via email

rohanKanojia commented Dec 5, 2022

rohanKanojia commented Jan 18, 2023

manusa commented Jan 18, 2023

rohanKanojia commented Jan 18, 2023

manusa commented Jan 18, 2023 •

edited

Loading

rohanKanojia commented Jan 18, 2023 •

edited

Loading

rohanKanojia commented Jan 18, 2023

manusa commented Jan 18, 2023

Build going into inifinite loop on running mvn oc:build -Dorg.slf4j.simpleLogger.defaultLogLevel=trace` #1950

Build going into inifinite loop on running mvn oc:build -Dorg.slf4j.simpleLogger.defaultLogLevel=trace` #1950

Comments

rohanKanojia commented Nov 30, 2022 • edited Loading

Describe the bug

Eclipse JKube version

Component

Apache Maven version

Gradle version

Steps to reproduce

Expected behavior

Runtime

Kubernetes API Server version

Environment

Eclipse JKube Logs

Sample Reproducer Project

Additional context

DhirajSardar commented Dec 2, 2022

rohanKanojia commented Dec 2, 2022

DhirajSardar commented Dec 3, 2022 via email

rohanKanojia commented Dec 5, 2022

rohanKanojia commented Jan 18, 2023

manusa commented Jan 18, 2023

rohanKanojia commented Jan 18, 2023

manusa commented Jan 18, 2023 • edited Loading

rohanKanojia commented Jan 18, 2023 • edited Loading

rohanKanojia commented Jan 18, 2023

manusa commented Jan 18, 2023

Build going into inifinite loop on running `mvn oc:build -Dorg.slf4j.simpleLogger.defaultLogLevel=trace`` #1950

Build going into inifinite loop on running `mvn oc:build -Dorg.slf4j.simpleLogger.defaultLogLevel=trace`` #1950

rohanKanojia commented Nov 30, 2022 •

edited

Loading

manusa commented Jan 18, 2023 •

edited

Loading

rohanKanojia commented Jan 18, 2023 •

edited

Loading