Skip to content

Conversation

@olivierlemasle
Copy link
Contributor

@olivierlemasle olivierlemasle commented Apr 20, 2016

Fixes JSON deserialization of cmdInfo (current process fails with StringIndexOutOfBoundsException when cmdEventType is the last parameter in the JSON string).

A StringIndexOutOfBoundsException is thrown in some cases during event publication.

Example: a stopVirtualMachine API request is executed, and fails with:

2016-04-15 09:24:43,080 ERROR [o.a.c.f.m.MessageDispatcher] (catalina-exec-1:ctx-840cbaa7 ctx-8daf0e9c ctx-f63af073) Unexpected exception when calling com.cloud.api.ApiServer.handleAsyncJobPublishEvent
java.lang.reflect.InvocationTargetException
        at sun.reflect.GeneratedMethodAccessor307.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.cloudstack.framework.messagebus.MessageDispatcher.dispatch(MessageDispatcher.java:75)
        at org.apache.cloudstack.framework.messagebus.MessageDispatcher.onPublishMessage(MessageDispatcher.java:45)
        at org.apache.cloudstack.framework.messagebus.MessageBusBase$SubscriptionNode.notifySubscribers(MessageBusBase.java:441)
        at org.apache.cloudstack.framework.messagebus.MessageBusBase.publish(MessageBusBase.java:178)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.publishOnEventBus(AsyncJobManagerImpl.java:1052)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:180)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:168)
        at com.cloud.api.ApiServer.queueCommand(ApiServer.java:687)
        at com.cloud.api.ApiServer.handleRequest(ApiServer.java:528)
        at com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:296)
        at com.cloud.api.ApiServlet$1.run(ApiServlet.java:127)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:124)
        at com.cloud.api.ApiServlet.doGet(ApiServlet.java:86)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:620)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1040)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1720)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1679)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.StringIndexOutOfBoundsException: String index out of range: -468
        at java.lang.String.substring(String.java:1967)
        at com.cloud.api.ApiServer.handleAsyncJobPublishEvent(ApiServer.java:270)
        at sun.reflect.GeneratedMethodAccessor307.invoke(Unknown Source)
        ... 41 more

The VM is not stopped, and the API returns the following error:

  HTTP/1.1 530 : InvocationTargetException when invoking event handler for subject: job.eventpublish

The error comes from JSON parsing in

cmdEventType = info.substring(begin + marker.length() + 2, info.indexOf(",", begin) - 1);

The substring() method throws a StringIndexOutOfBoundsException when cmdEventType is the last field in the JSON object.

The JSON object being the JSON serialization of a HashMap object, the order of the fields is not guaranteed. In my tests, I observed that there is no error with Java 7, but it fails with Java 8, which has a different Hashmap implementation.

For example, with request http://127.0.0.1:8096/client/api?command=stopVirtualMachine&id=734ef752-fe99-4d46-8f31-18130496473c, cmdInfo is:

{"ctxUserId":"1","httpmethod":"GET","ctxStartEventId":"105","id":"734ef752-fe99-4d46-8f31-18130496473c","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"734ef752-fe99-4d46-8f31-18130496473c\"}","ctxAccountId":"1","uuid":"734ef752-fe99-4d46-8f31-18130496473c","cmdEventType":"VM.STOP"}

and it fails.

Please note that the error is not present for all API requests, depending on the parameters fields.

if (begin >= 0) {
cmdEventType = info.substring(begin + marker.length() + 2, info.indexOf(",", begin) - 1);
Type type = new TypeToken<Map<String, Object>>(){}.getType();
Map<String, Object> cmdInfo = ApiGsonHelper.getBuilder().create().fromJson(info, type);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

is this Object necessary as the mapped type? Couldn't it be String directly? If you are using the api solely for collecting the cmdEventType, you could build the objects as String already and the typecheck on line 272 would be unnecessary.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@alexandrelimassantana You're right, it was unnecessary. I've updated the pull request accordingly.

@olivierlemasle olivierlemasle force-pushed the fix-CLOUDSTACK-9358 branch 5 times, most recently from de0959c to d025cd6 Compare May 3, 2016 22:16
Fixes JSON deserialization of cmdInfo (current process fails with
StringIndexOutOfBoundsException when cmdEventType is the last parameter
in the JSON string.
@olivierlemasle olivierlemasle force-pushed the fix-CLOUDSTACK-9358 branch from d025cd6 to 61d2692 Compare May 3, 2016 23:15
@olivierlemasle
Copy link
Contributor Author

Any chance reviewing this pull request?
The error is quite critical because it causes HTTP 530 errors in API requests.

Thanks!

CC @swill @rhtyd @DaanHoogland

@DaanHoogland
Copy link
Contributor

LGTM, always better to have real json handling as opposed to string parsing. @swill, can you schedule the integration suite on this?

@swill
Copy link
Contributor

swill commented May 12, 2016

@DaanHoogland & @olivierlemasle thanks for the heads up guys. I will get CI run against this today...

@olivierlemasle
Copy link
Contributor Author

Thanks @swill !

@swill
Copy link
Contributor

swill commented May 13, 2016

CI RESULTS

Tests Run: 82
  Skipped: 0
   Failed: 0
   Errors: 3
 Duration: 8h 28m 52s

Summary of the problem(s):

ERROR: test suite for <class 'integration.smoke.test_vpc_vpn.TestRVPCSite2SiteVpn'>
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/suite.py", line 209, in run
    self.setUp()
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/suite.py", line 292, in setUp
    self.setupContext(ancestor)
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/suite.py", line 315, in setupContext
    try_run(context, names)
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/util.py", line 471, in try_run
    return func()
  File "/data/git/cs1/cloudstack/test/integration/smoke/test_vpc_vpn.py", line 835, in setUpClass
    cls.template.download(cls.apiclient)
  File "/usr/lib/python2.7/site-packages/marvin/lib/base.py", line 1350, in download
    elif 'Downloaded' in template.status:
TypeError: argument of type 'NoneType' is not iterable
----------------------------------------------------------------------
Additional details in: /tmp/MarvinLogs/test_network_W3KO3O/results.txt
ERROR: test suite for <class 'integration.smoke.test_vpc_vpn.TestVpcRemoteAccessVpn'>
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/suite.py", line 209, in run
    self.setUp()
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/suite.py", line 292, in setUp
    self.setupContext(ancestor)
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/suite.py", line 315, in setupContext
    try_run(context, names)
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/util.py", line 471, in try_run
    return func()
  File "/data/git/cs1/cloudstack/test/integration/smoke/test_vpc_vpn.py", line 293, in setUpClass
    cls.template.download(cls.apiclient)
  File "/usr/lib/python2.7/site-packages/marvin/lib/base.py", line 1350, in download
    elif 'Downloaded' in template.status:
TypeError: argument of type 'NoneType' is not iterable
----------------------------------------------------------------------
Additional details in: /tmp/MarvinLogs/test_network_W3KO3O/results.txt
ERROR: test suite for <class 'integration.smoke.test_vpc_vpn.TestVpcSite2SiteVpn'>
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/suite.py", line 209, in run
    self.setUp()
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/suite.py", line 292, in setUp
    self.setupContext(ancestor)
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/suite.py", line 315, in setupContext
    try_run(context, names)
  File "/usr/lib/python2.7/site-packages/nose-1.3.7-py2.7.egg/nose/util.py", line 471, in try_run
    return func()
  File "/data/git/cs1/cloudstack/test/integration/smoke/test_vpc_vpn.py", line 472, in setUpClass
    cls.template.download(cls.apiclient)
  File "/usr/lib/python2.7/site-packages/marvin/lib/base.py", line 1350, in download
    elif 'Downloaded' in template.status:
TypeError: argument of type 'NoneType' is not iterable
----------------------------------------------------------------------
Additional details in: /tmp/MarvinLogs/test_network_W3KO3O/results.txt

Associated Uploads

/tmp/MarvinLogs/DeployDataCenter__May_12_2016_22_19_57_00T0NU:

/tmp/MarvinLogs/test_network_W3KO3O:

/tmp/MarvinLogs/test_vpc_routers_2D8M4Q:

Uploads will be available until 2016-07-13 02:00:00 +0200 CEST

Comment created by upr comment.

@swill
Copy link
Contributor

swill commented May 13, 2016

I have never seen these test failures before, so I believe they are somehow related to this change. @olivierlemasle can you review the CI results and post your feedback. Thanks...

@olivierlemasle
Copy link
Contributor Author

In the three tracebacks, the error is located in

elif 'Downloaded' in template.status:
and occurs because template.status is equal to None.

This comes from the Template.list(...) request just before, which has the following response (cf logs):

[
  {
   domain : u'ROOT',
   domainid : u'83f831cd-187e-11e6-92ee-5254001daa61',
   ostypename : u'Other PV (64-bit)',
   zoneid : u'fbbb2ed8-1929-42df-ad74-2a7a2639798c',
   displaytext : u'macchinina kvm',
   ostypeid : u'83e88c7d-187e-11e6-92ee-5254001daa61',
   passwordenabled : False, id : u'5c21909e-c641-42d8-b90f-f6795da7d9fb',
   isready : False,
   format : u'QCOW2',
   templatetype : u'USER',
   zonename : u'MCCT-SHARED-1',
   isdynamicallyscalable : False,
   tags : [],
   isfeatured : False,
   sshkeyenabled : False,
   isextractable : False,
   crossZones : False,
   account : u'test-TestRouterRules-test_10_destroy_cpvm-LXQSYL',
   name : u'tiny-kvm-D9K3XF',
   hypervisor : u'KVM',
   ispublic : False,
   checksum : u'f50acb3a4387019b473d0f25a42bf06e'
 }
]

As you can see, there's no "status" in this response.
So somehow, the issue is due to the fact that a listTemplates request returned a result without status during a template download.

I cannot see how it can be related to this change. Moreover, I tested my pull request, and my tests included a template download and a VM deployment.

@swill Is it possible that an error in the template download would cause the absence of the status field, and therefore this error?

@swill
Copy link
Contributor

swill commented May 13, 2016

I am running my CI against it again to make sure this does not pop again. If it doesn't then I will merge it right away as Jenkins and Travis are green. Thx...

@swill
Copy link
Contributor

swill commented May 17, 2016

CI RESULTS

Tests Run: 85
  Skipped: 0
   Failed: 1
   Errors: 1
 Duration: 10h 57m 29s

Summary of the problem(s):

ERROR: Test to verify access to loadbalancer haproxy admin stats page
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/git/cs1/cloudstack/test/integration/smoke/test_internal_lb.py", line 854, in tearDown
    raise Exception("Cleanup failed with %s" % e)
Exception: Cleanup failed with Job failed: {jobprocstatus : 0, created : u'2016-05-17T05:52:58+0200', jobresult : {errorcode : 530, errortext : u'Failed to delete network'}, cmd : u'org.apache.cloudstack.api.command.user.network.DeleteNetworkCmd', userid : u'25043b8f-1bb4-11e6-9240-5254001daa61', jobstatus : 2, jobid : u'ad0c2203-120d-45fb-a6c9-1bbe0da19514', jobresultcode : 530, jobresulttype : u'object', jobinstancetype : u'Network', accountid : u'250420c3-1bb4-11e6-9240-5254001daa61'}
----------------------------------------------------------------------
Additional details in: /tmp/MarvinLogs/test_network_9KDC6J/results.txt
FAIL: Test destroy(expunge) Virtual Machine
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/git/cs1/cloudstack/test/integration/smoke/test_vm_life_cycle.py", line 646, in test_09_expunge_vm
    self.assertEqual(list_vm_response,None,"Check Expunged virtual machine is in listVirtualMachines response")
AssertionError: Check Expunged virtual machine is in listVirtualMachines response
----------------------------------------------------------------------
Additional details in: /tmp/MarvinLogs/test_vpc_routers_K7V5E5/results.txt

Associated Uploads

/tmp/MarvinLogs/DeployDataCenter__May_17_2016_00_21_26_CF1ATO:

/tmp/MarvinLogs/test_network_9KDC6J:

/tmp/MarvinLogs/test_vpc_routers_K7V5E5:

Uploads will be available until 2016-07-17 02:00:00 +0200 CEST

Comment created by upr comment.

@swill
Copy link
Contributor

swill commented May 17, 2016

retesting the failure now...

@swill
Copy link
Contributor

swill commented May 17, 2016

CI RESULTS

Tests Run: 126
  Skipped: 0
   Failed: 2
   Errors: 2
 Duration: 13h 11m 51s

Summary of the problem(s):

ERROR: test_09_create_redundant_vpc_offering (integration.component.test_vpc_offerings.TestVPCOffering)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/git/cs1/cloudstack/test/integration/component/test_vpc_offerings.py", line 1178, in test_09_create_redundant_vpc_offering
    domainid=self.account.domainid
  File "/usr/lib/python2.7/site-packages/marvin/lib/base.py", line 4311, in create
    return VPC(apiclient.createVPC(cmd).__dict__)
  File "/usr/lib/python2.7/site-packages/marvin/cloudstackAPI/cloudstackAPIClient.py", line 2415, in createVPC
    response = self.connection.marvinRequest(command, response_type=response, method=method)
  File "/usr/lib/python2.7/site-packages/marvin/cloudstackConnection.py", line 379, in marvinRequest
    raise e
Exception: Job failed: {jobprocstatus : 0, created : u'2016-05-17T16:26:26+0200', jobresult : {errorcode : 530, errortext : u'Failed to create VPC'}, cmd : u'org.apache.cloudstack.api.command.admin.vpc.CreateVPCCmdByAdmin', userid : u'25043b8f-1bb4-11e6-9240-5254001daa61', jobstatus : 2, jobid : u'c66917dd-cfc3-43cf-bae9-e414169536c1', jobresultcode : 530, jobresulttype : u'object', jobinstancetype : u'None', accountid : u'250420c3-1bb4-11e6-9240-5254001daa61'}
----------------------------------------------------------------------
Additional details in: /tmp/MarvinLogs/test_vpc_routers_F3EPYY/results.txt
FAIL: Test destroy(expunge) Virtual Machine
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/git/cs1/cloudstack/test/integration/smoke/test_vm_life_cycle.py", line 646, in test_09_expunge_vm
    self.assertEqual(list_vm_response,None,"Check Expunged virtual machine is in listVirtualMachines response")
AssertionError: Check Expunged virtual machine is in listVirtualMachines response
----------------------------------------------------------------------
Additional details in: /tmp/MarvinLogs/test_vpc_routers_F3EPYY/results.txt
ERROR: Test to verify access to loadbalancer haproxy admin stats page
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/git/cs1/cloudstack/test/integration/smoke/test_internal_lb.py", line 854, in tearDown
    raise Exception("Cleanup failed with %s" % e)
Exception: Cleanup failed with Job failed: {jobprocstatus : 0, created : u'2016-05-17T05:52:58+0200', jobresult : {errorcode : 530, errortext : u'Failed to delete network'}, cmd : u'org.apache.cloudstack.api.command.user.network.DeleteNetworkCmd', userid : u'25043b8f-1bb4-11e6-9240-5254001daa61', jobstatus : 2, jobid : u'ad0c2203-120d-45fb-a6c9-1bbe0da19514', jobresultcode : 530, jobresulttype : u'object', jobinstancetype : u'Network', accountid : u'250420c3-1bb4-11e6-9240-5254001daa61'}
----------------------------------------------------------------------
Additional details in: /tmp/MarvinLogs/test_network_9KDC6J/results.txt
FAIL: Test destroy(expunge) Virtual Machine
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/git/cs1/cloudstack/test/integration/smoke/test_vm_life_cycle.py", line 646, in test_09_expunge_vm
    self.assertEqual(list_vm_response,None,"Check Expunged virtual machine is in listVirtualMachines response")
AssertionError: Check Expunged virtual machine is in listVirtualMachines response
----------------------------------------------------------------------
Additional details in: /tmp/MarvinLogs/test_vpc_routers_K7V5E5/results.txt

Associated Uploads

/tmp/MarvinLogs/DeployDataCenter__May_17_2016_00_21_26_CF1ATO:

/tmp/MarvinLogs/test_network_9KDC6J:

/tmp/MarvinLogs/test_vpc_routers_F3EPYY:

/tmp/MarvinLogs/test_vpc_routers_K7V5E5:

Uploads will be available until 2016-07-17 02:00:00 +0200 CEST

Comment created by upr comment.

@olivierlemasle
Copy link
Contributor Author

Ok.... Still the same error.

I still don't think it's related to my change. The same error occured before, for example for #1529

Do you know why the tests are failing?

@swill
Copy link
Contributor

swill commented May 18, 2016

CI RESULTS

Tests Run: 85
  Skipped: 0
   Failed: 1
   Errors: 1
 Duration: 11h 12m 43s

Summary of the problem(s):

ERROR: Test to verify access to loadbalancer haproxy admin stats page
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/git/cs1/cloudstack/test/integration/smoke/test_internal_lb.py", line 854, in tearDown
    raise Exception("Cleanup failed with %s" % e)
Exception: Cleanup failed with Job failed: {jobprocstatus : 0, created : u'2016-05-18T06:22:16+0200', jobresult : {errorcode : 530, errortext : u'Failed to delete network'}, cmd : u'org.apache.cloudstack.api.command.user.network.DeleteNetworkCmd', userid : u'09a5b54a-1c81-11e6-91b2-5254001daa61', jobstatus : 2, jobid : u'781934ed-fbef-4d01-ac31-88a8d038be85', jobresultcode : 530, jobresulttype : u'object', jobinstancetype : u'Network', accountid : u'09a59c9c-1c81-11e6-91b2-5254001daa61'}
----------------------------------------------------------------------
Additional details in: /tmp/MarvinLogs/test_network_M88ZOW/results.txt
FAIL: Test destroy(expunge) Virtual Machine
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/data/git/cs1/cloudstack/test/integration/smoke/test_vm_life_cycle.py", line 646, in test_09_expunge_vm
    self.assertEqual(list_vm_response,None,"Check Expunged virtual machine is in listVirtualMachines response")
AssertionError: Check Expunged virtual machine is in listVirtualMachines response
----------------------------------------------------------------------
Additional details in: /tmp/MarvinLogs/test_vpc_routers_PNMN65/results.txt

Associated Uploads

/tmp/MarvinLogs/DeployDataCenter__May_18_2016_00_48_16_0H13WE:

/tmp/MarvinLogs/test_network_M88ZOW:

/tmp/MarvinLogs/test_vpc_routers_PNMN65:

Uploads will be available until 2016-07-18 02:00:00 +0200 CEST

Comment created by upr comment.

@swill
Copy link
Contributor

swill commented May 18, 2016

Im not sure. I need to check the mailing list to see if there are other PRs with similar errors. It seems to have the same errors for the past 3 runs, so it seems pretty consistent (unfortunately).

@asfgit asfgit merged commit 61d2692 into apache:master May 26, 2016
asfgit pushed a commit that referenced this pull request May 26, 2016
CLOUDSTACK-9358: StringIndexOutOfBoundsException on eventsFixes JSON deserialization of `cmdInfo` (current process fails with `StringIndexOutOfBoundsException` when `cmdEventType` is the last parameter in the JSON string).

A `StringIndexOutOfBoundsException` is thrown in some cases during event publication.

Example: a stopVirtualMachine API request is executed, and fails with:

```
2016-04-15 09:24:43,080 ERROR [o.a.c.f.m.MessageDispatcher] (catalina-exec-1:ctx-840cbaa7 ctx-8daf0e9c ctx-f63af073) Unexpected exception when calling com.cloud.api.ApiServer.handleAsyncJobPublishEvent
java.lang.reflect.InvocationTargetException
        at sun.reflect.GeneratedMethodAccessor307.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.apache.cloudstack.framework.messagebus.MessageDispatcher.dispatch(MessageDispatcher.java:75)
        at org.apache.cloudstack.framework.messagebus.MessageDispatcher.onPublishMessage(MessageDispatcher.java:45)
        at org.apache.cloudstack.framework.messagebus.MessageBusBase$SubscriptionNode.notifySubscribers(MessageBusBase.java:441)
        at org.apache.cloudstack.framework.messagebus.MessageBusBase.publish(MessageBusBase.java:178)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.publishOnEventBus(AsyncJobManagerImpl.java:1052)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:180)
        at org.apache.cloudstack.framework.jobs.impl.AsyncJobManagerImpl.submitAsyncJob(AsyncJobManagerImpl.java:168)
        at com.cloud.api.ApiServer.queueCommand(ApiServer.java:687)
        at com.cloud.api.ApiServer.handleRequest(ApiServer.java:528)
        at com.cloud.api.ApiServlet.processRequestInContext(ApiServlet.java:296)
        at com.cloud.api.ApiServlet$1.run(ApiServlet.java:127)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext$1.call(DefaultManagedContext.java:56)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.callWithContext(DefaultManagedContext.java:103)
        at org.apache.cloudstack.managed.context.impl.DefaultManagedContext.runWithContext(DefaultManagedContext.java:53)
        at com.cloud.api.ApiServlet.processRequest(ApiServlet.java:124)
        at com.cloud.api.ApiServlet.doGet(ApiServlet.java:86)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:620)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
        at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
        at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1040)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1720)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1679)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.StringIndexOutOfBoundsException: String index out of range: -468
        at java.lang.String.substring(String.java:1967)
        at com.cloud.api.ApiServer.handleAsyncJobPublishEvent(ApiServer.java:270)
        at sun.reflect.GeneratedMethodAccessor307.invoke(Unknown Source)
        ... 41 more
```

The VM is not stopped, and the API returns the following error:

      HTTP/1.1 530 : InvocationTargetException when invoking event handler for subject: job.eventpublish

The error comes from JSON parsing in https://github.com/apache/cloudstack/blob/339355594ca537ebbc8e0a0f6e49a63ee4b884ac/server/src/com/cloud/api/ApiServer.java#L270

The `substring()` method throws a StringIndexOutOfBoundsException when `cmdEventType` is the last field in the JSON object.

The JSON object being the JSON serialization of a `HashMap` object, the order of the fields is not guaranteed. In my tests, I observed that there is no error with Java 7, but it fails with Java 8, which has a different Hashmap implementation.

For example, with request http://127.0.0.1:8096/client/api?command=stopVirtualMachine&id=734ef752-fe99-4d46-8f31-18130496473c, cmdInfo is:

```
{"ctxUserId":"1","httpmethod":"GET","ctxStartEventId":"105","id":"734ef752-fe99-4d46-8f31-18130496473c","ctxDetails":"{\"interface com.cloud.vm.VirtualMachine\":\"734ef752-fe99-4d46-8f31-18130496473c\"}","ctxAccountId":"1","uuid":"734ef752-fe99-4d46-8f31-18130496473c","cmdEventType":"VM.STOP"}
```

and it fails.

Please note that the error is not present for all API requests, depending on the parameters fields.

* pr/1503:
  CLOUDSTACK-9358: StringIndexOutOfBoundsException on events

Signed-off-by: Will Stevens <williamstevens@gmail.com>
nathanejohnson added a commit to myENA/cloudstack that referenced this pull request Nov 8, 2016
apache#1503
Fixes Index out of range exception on events
@olivierlemasle olivierlemasle deleted the fix-CLOUDSTACK-9358 branch March 16, 2017 16:28
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants