-
Bug
-
Resolution: Done
-
Medium
-
Guilin Release, Guilin Maintenance Release 1
-
None
CDS post config fails to store stack status to database in Guilin, even though the same works for Frankfurt. See comparison below:
/app/logs/openstack $ more debug.log | grep -B10 -A10 'Performing post processing backout' {{ "self" :}} {{ { "href" : "http://so-request-db-adapter.onap:8083/requestProcessingData/10" } }} , {{ "requestProcessingData" :}} {{ { "href" : "http://so-request-db-adapter.onap:8083/requestProcessingData/10" } }} } {{ }}} {{ 2020-11-26T12:25:44.501Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|o.o.l.filter.spring.SpringClientPayloadFilter - =======================response end=================================================}} {{ 2020-11-26T12:25:57.222Z||org.onap.so.db.connections.ScheduledDnsLookup - Switched Database IP Address from 10.42.1.38 to 10.42.3.54}} {{ 2020-11-26T12:26:00.932Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|org.onap.so.openstack.utils.MsoHeatUtils - Performing post processing backout: true cleanUpKeyPair: true, stack Stack{description='O-RAN Simulator', links=[Link}} {{ {href='http://106.120.119.17:8004/v1/b1ce7742d956463999923ceaed71786e/stacks/ORAN_Service_064daa43-vfw/69d2a832-ec57-4dd6-b9f7-6224b51c5788', rel='self'} }} ], stackStatusReason='Stack CREATE completed successfully', stackName='ORAN_Service_064daa43-vfw', updatedTime=null, creationTime=Thu Nov 26 12:25:25 GMT 2020, stackStatus='CREATE_COMPLETE', id='69d2a832-ec57-4dd6-b9f7-6224b51c5788', outputs='[Output [key=oam_management_v4_address, value=106.120.119.157]]', parameters='{OS::project_id=b1ce7742d956463999923ceaed71786e, OS::stack_id=69d2a832-ec57-4dd6-b9f7-6224b51c5788, OS::stack_name=ORAN_Service_064daa43-vfw, sdnc_artifact_name=vnf, image=ran-sim-STAGING, sdnc_model_version=1.2.2, net=public, sdnc_model_name=oran_simulator_for_phase3, flavor=m1.large, skip_post_instantiation_configuration=False}', files='null'} {{ 2020-11-26T12:26:00.937Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|o.onap.logging.filter.base.AbstractMetricLogFilter - Could not Target Entity: http://so-request-db-adapter.onap:8083/infraActiveRequests/e4217a16-5e24-47e9-a6b4-bff0bafaef45}} {{ 2020-11-26T12:26:00.950Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|o.o.l.filter.spring.SpringClientPayloadFilter - ===========================request begin================================================}} {{ 2020-11-26T12:26:00.950Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|o.o.l.filter.spring.SpringClientPayloadFilter - URI : http://so-request-db-adapter.onap:8083/infraActiveRequests/e4217a16-5e24-47e9-a6b4-bff0bafaef45}} {{ 2020-11-26T12:26:00.951Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|o.o.l.filter.spring.SpringClientPayloadFilter - Method : PATCH}} {{ 2020-11-26T12:26:00.952Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|o.o.l.filter.spring.SpringClientPayloadFilter - Headers : [Accept:"application/json", Authorization:"Basic YnBlbDpwYXNzd29yZDEk", Content-Type:"application/json", Content-Length:"258", X-ONAP-RequestID:"e4217a16-5e24-47e9-a6b4-bff0bafaef45", X-RequestID:"e4217a16-5e24-47e9-a6b4-bff0bafaef45", X-TransactionID:"e4217a16-5e24-47e9-a6b4-bff0bafaef45", X-ECOMP-RequestID:"e4217a16-5e24-47e9-a6b4-bff0bafaef45", X-ONAP-PartnerName:"UNKNOWN", X-InvocationID:"470ee1aa-d02c-4eda-8bc8-6e8339fca9ae"]}} {{ 2020-11-26T12:26:00.952Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|o.o.l.filter.spring.SpringClientPayloadFilter - Request body: {"requestId":"e4217a16-5e24-47e9-a6b4-bff0bafaef45","resourceStatusMessage":"The vf module was found to already exist, thus no new vf module was created in the cloud via this request","cloudApiRequests":[],"requestURI":"e4217a16-5e24-47e9-a6b4-bff0bafaef45"}}} {{ 2020-11-26T12:26:00.952Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|o.o.l.filter.spring.SpringClientPayloadFilter - ==========================request end================================================}} {{ 2020-11-26T12:26:00.963Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|o.onap.logging.filter.base.AbstractMetricLogFilter - Could not Target Entity: http://so-request-db-adapter.onap:8083/requestProcessingData/search/findOneBySoRequestIdAndGroupingIdAndName?SO_REQUEST_ID=e4217a16-5e24-47e9-a6b4-bff0bafaef45&NAME=ORAN_Service_064daa43-vfw&GROUPING_ID=69d2a832-ec57-4dd6-b9f7-6224b51c5788}} {{ 2020-11-26T12:26:00.965Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|o.o.l.filter.spring.SpringClientPayloadFilter - ===========================request begin================================================}} {{ 2020-11-26T12:26:00.965Z|e4217a16-5e24-47e9-a6b4-bff0bafaef45|o.o.l.filter.spring.SpringClientPayloadFilter - URI : http://so-request-db-adapter.onap:8083/requestProcessingData/search/findOneBySoRequestIdAndGroupingIdAndName?SO_REQUEST_ID=e4217a16-5e24-47e9-a6b4-bff0bafaef45&NAME=ORAN_Service_064daa43-vfw&GROUPING_ID=69d2a832-ec57-4dd6-b9f7-6224b51c5788}} {{ /app/logs/openstack $}}
Guilin:
2020-11-25T18:38:22.383Z|69e858f8-add6-40f4-9967-0e5599f50203|org.onap.so.openstack.utils.MsoHeatUtils - Performing post processing backout: false cleanUpKeyPair: false, stack Stack{description='O-RAN Simulator', links=[Link {{ {href='http://106.120.119.17:8004/v1/b1ce7742d956463999923ceaed71786e/stacks/ORAN_Service_91523158-vfw/4be5ef2c-f699-476c-bd19-75d22155ef59', rel='self'} }} ], stackStatusReason='Stack CREATE completed successfully', stackName='ORAN_Service_91523158-vfw', updatedTime=null, creationTime=Wed Nov 25 18:37:13 GMT 2020, stackStatus='CREATE_COMPLETE', id='4be5ef2c-f699-476c-bd19-75d22155ef59', outputs='[Output [key=oam_management_v4_address, value=106.120.119.174]]', parameters='{OS::project_id=b1ce7742d956463999923ceaed71786e, OS::stack_id=4be5ef2c-f699-476c-bd19-75d22155ef59, OS::stack_name=ORAN_Service_91523158-vfw, sdnc_artifact_name=vnf, image=ran-sim-STAGING, sdnc_model_version=1.2.3, net=public, sdnc_model_name=oran_simulator_for_phase3, flavor=m1.large, skip_post_instantiation_configuration=False}', files='null'} {{ 2020-11-25T18:38:22.384Z||org.onap.so.openstack.utils.StackStatusHandler - Error adding stack status to request database}} {{ java.lang.IllegalArgumentException: Null value on 0 position}} {{ at org.apache.cxf.jaxrs.impl.UriBuilderImpl.toStringList(UriBuilderImpl.java:818)}} {{ at org.apache.cxf.jaxrs.impl.UriBuilderImpl.queryParam(UriBuilderImpl.java:710)}} {{ at org.onap.so.db.request.client.RequestsDbClient.getRequestProcessingDataBySoRequestIdAndNameAndGrouping(RequestsDbClient.java:386)}} {{ at org.onap.so.openstack.utils.StackStatusHandler.updateStackStatus(StackStatusHandler.java:51)}} {{ at org.onap.so.openstack.utils.StackStatusHandler$$FastClassBySpringCGLIB$$33f41b9.invoke(<generated>)}} {{ at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)}} {{ at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:749)}} {{ at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)}} {{ at org.springframework.aop.interceptor.AsyncExecutionInterceptor.lambda$invoke$0(AsyncExecutionInterceptor.java:115)}} {{ at java.base/java.util.concurrent.FutureTask.run(Unknown Source)}} {{ at java.base/java.lang.Thread.run(Unknown Source)}} {{ 2020-11-25T18:38:22.441Z|69e858f8-add6-40f4-9967-0e5599f50203|o.onap.so.adapters.tasks.orchestration.PollService - The External Task Id: 3cbdc8b7-2f4d-11eb-9312-56a6013b666c Successful}} {{ 2020-11-25T18:38:23.234Z|69e858f8-add6-40f4-9967-0e5599f50203|o.o.s.adapters.tasks.inventory.CreateInventoryTask - Executing External Task Create Inventory, Retry Number: null}} {{ org.onap.so.cloud.resource.beans.CloudInformation@7fd490ca}} {{ 2020-11-25T18:38:23.235Z|69e858f8-add6-40f4-9967-0e5599f50203|o.onap.logging.filter.base.AbstractMetricLogFilter - Could not Target Entity: http://so-catalog-db-adapter.onap:8082/cloudSite/RegionOne}} {{ 2020-11-25T18:38:23.235Z|69e858f8-add6-40f4-9967-0e5599f50203|o.o.l.filter.spring.SpringClientPayloadFilter - ===========================request begin================================================}} {{ 2020-11-25T18:38:23.235Z|69e858f8-add6-40f4-9967-0e5599f50203|o.o.l.filter.spring.SpringClientPayloadFilter - URI : http://so-catalog-db-adapter.onap:8082/cloudSite/RegionOne}} {{ 2020-11-25T18:38:23.235Z|69e858f8-add6-40f4-9967-0e5599f50203|o.o.l.filter.spring.SpringClientPayloadFilter - Method : GET}} {{ 2020-11-25T18:38:23.235Z|69e858f8-add6-40f4-9967-0e5599f50203|o.o.l.filter.spring.SpringClientPayloadFilter - Headers : [Accept:"application/hal+json", Content-Length:"0", Content-Type:"application/hal+json", X-ONAP-RequestID:"69e858f8-add6-40f4-9967-0e5599f50203", X-RequestID:"69e858f8-add6-40f4-9967-0e5599f50203", X-TransactionID:"69e858f8-add6-40f4-9967-0e5599f50203", X-ECOMP-RequestID:"69e858f8-add6-40f4-9967-0e5599f50203", X-ONAP-PartnerName:"UNKNOWN", X-InvocationID:"1418ae57-a5a4-4a79-b9cc-a8c5ce925f84"]}} {{ 2020-11-25T18:38:23.236Z|69e858f8-add6-40f4-9967-0e5599f50203|o.o.l.filter.spring.SpringClientPayloadFilter - Request body:}} {{ 2020-11-25T18:38:23.236Z|69e858f8-add6-40f4-9967-0e5599f50203|o.o.l.filter.spring.SpringClientPayloadFilter - ==========================request end================================================}}
As you may see from the stacktrace, problematic line is RequestsDbClient.java:386 :
UriBuilder.fromUri(endpoint + findBySoRequestIdAndGroupIdAndName).queryParam(SO_REQUEST_ID, soRequestId)
(this is part of method getRequestProcessingDataBySoRequestIdAndNameAndGrouping)
queryParam method is converting its arg list (soRequestId in this case) into a list, and fails with "java.lang.IllegalArgumentException: Null value on 0 position". This means soRequestId is null.
As you can see the method updateStackStatus is marked @Async and called as FutureTask, in a separate thread. Method updateStackStatus, from above, is taking all arguments sent to getRequestProcessingDataBySoRequestIdAndNameAndGrouping from MDC, which uses mdcAdapter, which seems to be initialized as LogbackMDCAdapter, which uses ThreadLocal. For fresh thread this structure would be empty.
Our guess is that in Frankfurt release this call is actually not asynchronous, but we are not able to find significant code differences that would support this hypothesis without debugging. There are differences, but none of them is related to hierarchy call, @Async or @EnableAsync directives.
On a side note, using logging framework to pass around this information seems to be problematic. Would be great to refactor this, if we have possibility.