[BUG] AzureResourceManager throws NullPointerException in context of ContainerGroup

[sparsick]

Describe the bug
When using many Azure container instances with private IP address, then the AzureResourceManager throws time to time NullPointerException in context of ContainerGroup.

Exception or Stack Trace

2022-02-11 09:01:42.674+0000 [id=74]    WARNING c.m.j.c.aci.AciCloud#lambda$provision$1: AciCloud: Provision agent test-private-n4s69 failed: java.lang.NullPointerException
java.lang.NullPointerException
        at com.azure.resourcemanager.containerinstance.implementation.ContainerGroupImpl.initializeChildrenFromInner(ContainerGroupImpl.java:217)
        at com.azure.resourcemanager.resources.fluentcore.arm.models.implementation.GroupableParentResourceImpl.<init>(GroupableParentResourceImpl.java:32)
        at com.azure.resourcemanager.containerinstance.implementation.ContainerGroupImpl.<init>(ContainerGroupImpl.java:73)
        at com.azure.resourcemanager.containerinstance.implementation.ContainerGroupsImpl.wrapModel(ContainerGroupsImpl.java:43)
        at com.azure.resourcemanager.containerinstance.implementation.ContainerGroupsImpl.wrapModel(ContainerGroupsImpl.java:24)
        at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:113)
        at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
        at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:151)
        at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)
        at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
        at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:249)
        at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:74)
        at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
        at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:249)
        at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1816)
        at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:249)
        at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:2398)
        at reactor.core.publisher.MonoFlatMap$FlatMapInner.onSubscribe(MonoFlatMap.java:238)
        at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:55)

To Reproduce
Steps to reproduce the behavior: see issue jenkinsci/azure-container-agents-plugin#101

Code Snippet
see

• https://github.com/jenkinsci/azure-container-agents-plugin/blob/a22f04771da02f714abab78022efdb38c8bc1fe3/src/main/java/com/microsoft/jenkins/containeragents/aci/AciCloud.java#L201
• https://github.com/jenkinsci/azure-container-agents-plugin/blob/a22f04771da02f714abab78022efdb38c8bc1fe3/src/main/java/com/microsoft/jenkins/containeragents/aci/AciCloud.java#L177

Expected behavior
No NullPointerException is thrown.

Setup (please complete the following information):

• OS: Ubuntu 18.04
• Library/Libraries: com.azure.resourcemanager:azure-resourcemanager-containerinstance:2.9.0
• Java version: 11
• Frameworks: Jenkins Plugin Azure Container Agent

Information Checklist
Kindly make sure that you have added all the following information above and checkoff the required fields otherwise we will treat the issuer as an incomplete report

• Bug Description Added
• Repro Steps Added
• Setup information Added

[joshfree]

Thanks for filing this github issue, @sparsick. @weidongxu-microsoft could you please help route this?

[XiaofeiCao]

@sparsick
Hi, it would help if you can provide additional logging information by initializing AzureResourceManager using something like the code below:

AzureResourceManager azureResourceManager = AzureResourceManager
            .configure()
            .withLogLevel(HttpLogDetailLevel.BODY_AND_HEADERS) // for enabling log
            .authenticate(credential, profile)

and provide log response from:

ContainerGroup containerGroup =
                    azureResourceManager.containerGroups().getByResourceGroup(resourceGroup, agent.getNodeName());

when the exception occurs.
(exception probably occur after actually receiving the response from remote server, so log information should be present)

And redact any sensitive information, thanks!

[XiaofeiCao]

There's a default log size limit, so if the upper code snippet can't log the response in complete, you can use following code to bypass it:

AzureResourceManager azureResourceManager = AzureResourceManager
        .configure()
        .withLogOptions(new HttpLogOptions()
            .setLogLevel(HttpLogDetailLevel.BODY_AND_HEADERS)
            .setResponseLogger((logger, loggingOptions) -> {
                final HttpResponse response = loggingOptions.getHttpResponse();

                String contentLengthString = response.getHeaderValue("Content-Length");
                String bodySize = (CoreUtils.isNullOrEmpty(contentLengthString))
                    ? "unknown-length body"
                    : contentLengthString + "-byte body";

                StringBuilder responseLogMessage = new StringBuilder();
                responseLogMessage.append("<-- ")
                    .append(response.getStatusCode())
                    .append(" ")
                    .append(response.getRequest().getUrl())
                    .append(" (")
                    .append(loggingOptions.getResponseDuration().toMillis())
                    .append(" ms, ")
                    .append(bodySize)
                    .append(")")
                    .append(System.lineSeparator());

                HttpResponse bufferedResponse = response.buffer();
                ByteArrayOutputStream outputStream = new ByteArrayOutputStream();
                WritableByteChannel bodyContentChannel = Channels.newChannel(outputStream);
                return bufferedResponse.getBody()
                    .flatMap(byteBuffer -> {
                        try {
                            bodyContentChannel.write(byteBuffer.duplicate());
                            return Mono.just(byteBuffer);
                        } catch (IOException ex) {
                            return Mono.error(ex);
                        }
                    })
                    .doFinally(ignored -> {
                        responseLogMessage.append(", Response body:")
                            .append(System.lineSeparator())
                            .append(outputStream.toString(StandardCharsets.UTF_8))
                            .append(System.lineSeparator())
                            .append(" <-- END HTTP");

                        logger.info(responseLogMessage.toString());

                    }).then(Mono.just(bufferedResponse));

            })
        )
        .authenticate(credential, profile)

[sparsick]

@XiaofeiCao the log information with your requested log level:

2022-02-16 14:09:29.645+0000 [id=79]    INFO    c.m.j.c.a.AciCleanTask$DeploymentRegistrar#registerDeployment: AzureAciCleanUpTask: registerDeployment: Registering deployment test-private-d3zld1qx in jenkins-rg
2022-02-16 14:09:29.890+0000 [id=79]    INFO    c.m.j.c.aci.AciService#createDeployment: Waiting for deployment test-private-d3zld1qx
2022-02-16 14:09:29.892+0000 [id=79]    INFO    c.a.c.util.logging.ClientLogger#info: --> GET https://management.azure.com/subscriptions/subscriptionId/resourcegroups/jenkins-rg/providers/Microsoft.Resources/deployments/test-private-d3zld1qx?api-version=REDACTEDTry count: 1(empty body)--> END GET
2022-02-16 14:09:39.959+0000 [id=79]    INFO    c.a.c.util.logging.ClientLogger#info: --> GET https://management.azure.com/subscriptions/subscriptionId/resourcegroups/jenkins-rg/providers/Microsoft.Resources/deployments/test-private-d3zld1qx?api-version=REDACTEDTry count: 1(empty body)--> END GET
2022-02-16 14:09:50.012+0000 [id=79]    INFO    c.a.c.util.logging.ClientLogger#info: --> GET https://management.azure.com/subscriptions/subscriptionId/resourcegroups/jenkins-rg/providers/Microsoft.Resources/deployments/test-private-d3zld1qx?api-version=REDACTEDTry count: 1(empty body)--> END GET
2022-02-16 14:10:00.043+0000 [id=79]    INFO    c.a.c.util.logging.ClientLogger#info: --> GET https://management.azure.com/subscriptions/subscriptionId/resourcegroups/jenkins-rg/providers/Microsoft.Resources/deployments/test-private-d3zld1qx?api-version=REDACTEDTry count: 1(empty body)--> END GET
2022-02-16 14:10:10.069+0000 [id=79]    INFO    c.a.c.util.logging.ClientLogger#info: --> GET https://management.azure.com/subscriptions/subscriptionId/resourcegroups/jenkins-rg/providers/Microsoft.Resources/deployments/test-private-d3zld1qx?api-version=REDACTEDTry count: 1(empty body)--> END GET
2022-02-16 14:10:20.100+0000 [id=79]    INFO    c.a.c.util.logging.ClientLogger#info: --> GET https://management.azure.com/subscriptions/subscriptionId/resourcegroups/jenkins-rg/providers/Microsoft.Resources/deployments/test-private-d3zld1qx?api-version=REDACTEDTry count: 1(empty body)--> END GET
2022-02-16 14:10:20.132+0000 [id=79]    INFO    c.m.j.c.aci.AciService#createDeployment: Deployment test-private-d3zld1qx succeed
2022-02-16 14:10:20.132+0000 [id=79]    INFO    c.m.j.c.aci.AciCloud#waitToOnline: Waiting agent test-private-5s16p to online
2022-02-16 14:10:20.133+0000 [id=79]    INFO    c.a.c.util.logging.ClientLogger#info: --> GET https://management.azure.com/subscriptions/subscriptionId/resourceGroups/jenkins-rg/providers/Microsoft.ContainerInstance/containerGroups/test-private-5s16p?api-version=REDACTEDTry count: 1(empty body)--> END GET
2022-02-16 14:10:20.272+0000 [id=79]    WARNING c.m.j.c.aci.AciCloud#waitToOnline: Waiting for Agent test-private-5s16p produces a NullPointerException, but it is ignored.
2022-02-16 14:10:35.519+0000 [id=79]    INFO    c.a.c.util.logging.ClientLogger#info: --> GET https://management.azure.com/subscriptions/subscriptionId/resourceGroups/jenkins-rg/providers/Microsoft.ContainerInstance/containerGroups/test-private-5s16p?api-version=REDACTEDTry count: 1(empty body)--> END GET

I added a workaround. Therefore, the log message looks a bit different from the original post.

[XiaofeiCao]

Hi @sparsick ,
Thanks for providing the information!
However, I don't see response body in your provided log, so I believe it exceeds the log limit size so the logger won't log it...
Please try the following code snippet:

AzureResourceManager azureResourceManager = AzureResourceManager
        .configure()
        .withLogOptions(new HttpLogOptions()
            .setLogLevel(HttpLogDetailLevel.BODY_AND_HEADERS)
            .setResponseLogger((logger, loggingOptions) -> {
                final HttpResponse response = loggingOptions.getHttpResponse();

                String contentLengthString = response.getHeaderValue("Content-Length");
                String bodySize = (CoreUtils.isNullOrEmpty(contentLengthString))
                    ? "unknown-length body"
                    : contentLengthString + "-byte body";

                StringBuilder responseLogMessage = new StringBuilder();
                responseLogMessage.append("<-- ")
                    .append(response.getStatusCode())
                    .append(" ")
                    .append(response.getRequest().getUrl())
                    .append(" (")
                    .append(loggingOptions.getResponseDuration().toMillis())
                    .append(" ms, ")
                    .append(bodySize)
                    .append(")")
                    .append(System.lineSeparator());

                HttpResponse bufferedResponse = response.buffer();
                ByteArrayOutputStream outputStream = new ByteArrayOutputStream();
                WritableByteChannel bodyContentChannel = Channels.newChannel(outputStream);
                return bufferedResponse.getBody()
                    .flatMap(byteBuffer -> {
                        try {
                            bodyContentChannel.write(byteBuffer.duplicate());
                            return Mono.just(byteBuffer);
                        } catch (IOException ex) {
                            return Mono.error(ex);
                        }
                    })
                    .doFinally(ignored -> {
                        responseLogMessage.append(", Response body:")
                            .append(System.lineSeparator())
                            .append(outputStream.toString(StandardCharsets.UTF_8))
                            .append(System.lineSeparator())
                            .append(" <-- END HTTP");

                        logger.info(responseLogMessage.toString());

                    }).then(Mono.just(bufferedResponse));

            })
        )
        .authenticate(credential, profile)

The log should look like :

13:41:13.035 [reactor-http-nio-2] INFO com.azure.resourcemanager.containerinstance.implementation.ContainerGroupsClientImpl$ContainerGroupsService.getByResourceGroup - <-- 200 https://management.azure.com/subscriptions/subscriptionId/resourceGroups/jenkins-rg/providers/Microsoft.ContainerInstance/containerGroups/test-private-5s16p?api-version=REDACTED (4701 ms, 3003-byte body)Response body:XXXXXX

Thanks!