Skip to content
This repository has been archived by the owner on Dec 22, 2022. It is now read-only.

error 500 on GET /collections/:lidvid:/products #17

Closed
tloubrieu-jpl opened this issue Apr 15, 2021 · 23 comments · Fixed by #37
Closed

error 500 on GET /collections/:lidvid:/products #17

tloubrieu-jpl opened this issue Apr 15, 2021 · 23 comments · Fixed by #37
Assignees
Labels
B12.0 bug Something isn't working c.api s.high

Comments

@tloubrieu-jpl
Copy link
Member

tloubrieu-jpl commented Apr 15, 2021

🐛 Describe the bug

📜 To Reproduce

Steps to reproduce the behavior:
Run request:
curl --location --request GET 'https://pds-gamma.jpl.nasa.gov/api/collections/urn:nasa:pds:insight_documents:document_mission::1.1/products?start=0&limit=10&fields=ops:Data_File_Info.ops:md5_checksum&only-summary=false'

The request returns an error 500

🕵️ Expected behavior

The request should return the list of products belonging to the collection urn:nasa:pds:insight_documents:document_mission::1.1

📚 Version of Software Used

version 0.1.0 of the API

🩺 Test Data / Additional context

Log message is:
Run request:
2021-04-15 14:56:03.689 DEBUG 3583235 --- [nio-8081-exec-1] lasticSearchRegistrySearchRequestBuilder : Request product reference documents from 0 for size 1
2021-04-15 14:56:03.768 DEBUG 3583235 --- [nio-8081-exec-1] lasticSearchRegistrySearchRequestBuilder : search product ref request :SearchRequest{searchType=QUERY_THEN_FETCH, indices=[registry-refs], indicesOptions=IndicesOptions[ignore_unavailable=false, allow_no_indices=true, expand_wildcards_open=true, expand_wildcards_closed=false, expand_wildcards_hidden=false, allow_aliases_to_multiple_indices=true, forbid_closed_indices=true, ignore_aliases=false, ignore_throttled=true], types=[], routing='null', preference='null', requestCache=null, scroll=null, maxConcurrentShardRequests=0, batchedReduceSize=512, preFilterShardSize=null, allowPartialSearchResults=null, localClusterAlias=null, getOrCreateAbsoluteStartMillis=-1, ccsMinimizeRoundtrips=true, source={"from":0,"size":1,"query":{"match":{"collection_lidvid":{"query":"urn:nasa:pds:insight_documents:document_mission::1.1","operator":"OR","prefix_length":0,"max_expansions":50,"fuzzy_transpositions":true,"lenient":false,"zero_terms_query":"NONE","auto_generate_synonyms_phrase_query":true,"boost":1.0}}}}}
2021-04-15 14:56:04.205 ERROR 3583235 --- [nio-8081-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.ClassCastException: java.lang.String cannot be cast to java.util.ArrayList] with root cause

java.lang.ClassCastException: java.lang.String cannot be cast to java.util.ArrayList
at gov.nasa.pds.api.engineering.elasticsearch.business.CollectionProductIterator.initProductIterator(CollectionProductIterator.java:143) ~[classes/:na]
at gov.nasa.pds.api.engineering.elasticsearch.business.CollectionProductIterator.(CollectionProductIterator.java:43) ~[classes/:na]
at gov.nasa.pds.api.engineering.elasticsearch.business.CollectionProductRelationships.iterator(CollectionProductRelationships.java:81) ~[classes/:na]
at gov.nasa.pds.api.engineering.controllers.MyCollectionsApiController.getProductChildren(MyCollectionsApiController.java:146) ~[classes/:na]
at gov.nasa.pds.api.engineering.controllers.MyCollectionsApiController.productsOfACollection(MyCollectionsApiController.java:93) ~[classes/:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_271]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_271]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_271]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_271]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190) ~[spring-web-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138) ~[spring-web-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105) ~[spring-webmvc-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:879) ~[spring-webmvc-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:793) ~[spring-webmvc-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040) ~[spring-webmvc-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943) ~[spring-webmvc-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:634) ~[tomcat-embed-core-9.0.36.jar:9.0.36]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) ~[tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.36.jar:9.0.36]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.36.jar:9.0.36]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.7.RELEASE.jar:5.2.7.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541) [tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) [tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) [tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) [tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:373) [tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) [tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) [tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590) [tomcat-embed-core-9.0.36.jar:9.0.36]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-9.0.36.jar:9.0.36]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_271]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_271]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-9.0.36.jar:9.0.36]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_271]

🏞Screenshots

🖥 System Info

  • OS: [e.g. iOS]
  • Browser [e.g. chrome, safari]
  • Version [e.g. 22]

** 🦄 Applicable requirements**

@tloubrieu-jpl tloubrieu-jpl added bug Something isn't working needs:triage labels Apr 15, 2021
@jordanpadams jordanpadams added this to the 06.Mary.Decker.Slaney milestone Apr 18, 2021
@jordanpadams jordanpadams changed the title error 500 on GET /collections/:ildvid:/products error 500 on GET /collections/:lidvid:/products Apr 18, 2021
@al-niessner
Copy link
Contributor

@tloubrieu-jpl @jordanpadams

This is working since NASA-PDS/pds-api#4 was completed on PR NASA-PDS/pds-api#11 and it has examples showing that this is working. Does this mean it just needs to be deployed?

@jordanpadams
Copy link
Member

@al-niessner per @tloubrieu-jpl

The pull request Al mentions is already deployed on the server. I believe the errors comes from a document in the registry which is not formatted as expected by the API. I need to track down this document and understand what is unusual about on pds-gamma since I can not reproduce that on my laptop.

re-assigning to @tloubrieu-jpl

@jordanpadams
Copy link
Member

closing per #17 (comment)

@tloubrieu-jpl
Copy link
Member Author

@jordanpadams I am not convinced this ticket should be closed yet, because of this comment #17 (comment)

@jordanpadams
Copy link
Member

thanks @tloubrieu-jpl who should we assign this task to then? are you able to look or should we have someone else?

@jordanpadams jordanpadams reopened this May 24, 2021
@tloubrieu-jpl
Copy link
Member Author

tloubrieu-jpl commented May 24, 2021

@jordanpadams I am slow on that. My plan next plan is to create a stable release (0.2.0) with the latest development that Al made and deploy it on pds-gamma. Then I can investigate that bug. i am also having some other issues to work on for the API. I will do a full day (minus meetings) on the API tomorrow but I start with NASA-PDS/registry-api#467 and maybe #10

I need to document the deployment on pds-gamma so that @al-niessner can do it and debug there. That is going to be useful for the performance ticket as we mentionned earlier.

@jordanpadams
Copy link
Member

ok thanks @tloubrieu-jpl

@tloubrieu-jpl
Copy link
Member Author

I confirm the error is still there after I upgraded the pds-gamma server to the latest version (0.2.0)

@al-niessner
Copy link
Contributor

al-niessner commented May 26, 2021

@jordanpadams @tloubrieu-jpl -- cannot duplicate

Just built the registry-api-service master branch and ran a curl of the form /collections/lidvid/products?start&limit&fields&summary and it worked (see below for gory details). Upgrade issue or something else?

$ curl -silent --header 'Accept: application/json' "http://localhost:8080/collections/urn:nasa:pds:izenberg_pdart14_meap:data_eetable::1.0/products?limit=1&start=0&fields=ops%3AData_File_Info.ops%3Amd5_checksum&only-summary=false"
HTTP/1.1 200 
Content-Type: application/json
Transfer-Encoding: chunked
Date: Wed, 26 May 2021 17:55:51 GMT

{"summary":{"start":0,"limit":1,"sort":[],"properties":["ops:Data_File_Info.ops:md5_checksum"]},"data":[{"id":"urn:nasa:pds:izenberg_pdart14_meap:data_eetable:ele_evt_12hr_orbit_2011-2012::1.0","type":"Product_Observational","title":"Mercury Energetic Electrons Events Table","investigations":[{"id":"urn:nasa:pds:context:investigation:mission.messenger","href":"http://localhost:8080/products/urn:nasa:pds:context:investigation:mission.messenger"}],"observing_system_components":[{"id":"urn:nasa:pds:context:instrument_host:spacecraft.mess","href":"http://localhost:8080/products/urn:nasa:pds:context:instrument_host:spacecraft.mess"},{"id":"urn:nasa:pds:context:instrument:ns.mess","href":"http://localhost:8080/products/urn:nasa:pds:context:instrument:ns.mess"}],"targets":[{"id":"urn:nasa:pds:context:target:planet.mercury","href":"http://localhost:8080/products/urn:nasa:pds:context:target:planet.mercury"}],"metadata":{"version":"1.0","label_url":"/var/local/harvest/archive/data_eetable/ele_evt_12hr_orbit_2011-2012.xml"},"properties":{"ops:Data_File_Info.ops:md5_checksum":"b97c2b729120caf4d48f1f1442181396"}}]}

Tried a non-existent lidvid too and it still "works"

$ curl -silent --header 'Accept: application/json' "http://localhost:8080/collections/urn:nasa:pds:izenberg_pdart14_meap:data_eetables::1.0/products?limit=1&start=0&fields=ops%3AData_File_Info.ops%3Amd5_checksum&only-summary=false"
HTTP/1.1 200 
Content-Type: application/json
Transfer-Encoding: chunked
Date: Wed, 26 May 2021 17:57:06 GMT

{"summary":{"start":0,"limit":1,"sort":[],"properties":[]}}

@tloubrieu-jpl
Copy link
Member Author

tloubrieu-jpl commented May 26, 2021 via email

@tloubrieu-jpl
Copy link
Member Author

@jordanpadams @tloubrieu-jpl -- cannot duplicate

Just built the registry-api-service master branch and ran a curl of the form /collections/lidvid/products?start&limit&fields&summary and it worked (see below for gory details). Upgrade issue or something else?

$ curl -silent --header 'Accept: application/json' "http://localhost:8080/collections/urn:nasa:pds:izenberg_pdart14_meap:data_eetable::1.0/products?limit=1&start=0&fields=ops%3AData_File_Info.ops%3Amd5_checksum&only-summary=false"
HTTP/1.1 200 
Content-Type: application/json
Transfer-Encoding: chunked
Date: Wed, 26 May 2021 17:55:51 GMT

{"summary":{"start":0,"limit":1,"sort":[],"properties":["ops:Data_File_Info.ops:md5_checksum"]},"data":[{"id":"urn:nasa:pds:izenberg_pdart14_meap:data_eetable:ele_evt_12hr_orbit_2011-2012::1.0","type":"Product_Observational","title":"Mercury Energetic Electrons Events Table","investigations":[{"id":"urn:nasa:pds:context:investigation:mission.messenger","href":"http://localhost:8080/products/urn:nasa:pds:context:investigation:mission.messenger"}],"observing_system_components":[{"id":"urn:nasa:pds:context:instrument_host:spacecraft.mess","href":"http://localhost:8080/products/urn:nasa:pds:context:instrument_host:spacecraft.mess"},{"id":"urn:nasa:pds:context:instrument:ns.mess","href":"http://localhost:8080/products/urn:nasa:pds:context:instrument:ns.mess"}],"targets":[{"id":"urn:nasa:pds:context:target:planet.mercury","href":"http://localhost:8080/products/urn:nasa:pds:context:target:planet.mercury"}],"metadata":{"version":"1.0","label_url":"/var/local/harvest/archive/data_eetable/ele_evt_12hr_orbit_2011-2012.xml"},"properties":{"ops:Data_File_Info.ops:md5_checksum":"b97c2b729120caf4d48f1f1442181396"}}]}

Tried a non-existent lidvid too and it still "works"

$ curl -silent --header 'Accept: application/json' "http://localhost:8080/collections/urn:nasa:pds:izenberg_pdart14_meap:data_eetables::1.0/products?limit=1&start=0&fields=ops%3AData_File_Info.ops%3Amd5_checksum&only-summary=false"
HTTP/1.1 200 
Content-Type: application/json
Transfer-Encoding: chunked
Date: Wed, 26 May 2021 17:57:06 GMT

{"summary":{"start":0,"limit":1,"sort":[],"properties":[]}}

Actually that is a behavior I removed on purpose as an interim solution, see comments in the code at line

/* REMOVED since it breaks the result when only-smmary argument is set to true

To make that work again I would make getProductChildren throw an exception (e.g. LidVidNotFoundException) and trigger the 404 error on when this exception is raised.

@tloubrieu-jpl
Copy link
Member Author

@al-niessner i am working on the exception management for the not found lidvid now.

@al-niessner
Copy link
Contributor

@jordanpadams @tloubrieu-jpl

Main point of the two curls above are that neither causes error 500. So, how to either replicate original error or why does pds-gamma after upgrade still produce a 500 error?

@tloubrieu-jpl
Copy link
Member Author

tloubrieu-jpl commented May 26, 2021

@al-niessner I am pretty sure the error comes from the data we have in the registry on pds-gamma.

I will debug that by adding log messages if needed on the pds-gamma deployment, so to identify the eleasticSearch object which makes the software fail.

@al-niessner
Copy link
Contributor

@tloubrieu-jpl

Ah, is it possible that it is trying to return so much data that it causes a MemoryError? If so, does this mean it will be fixed (potentially) by NASA-PDS/pds-api#13?

@tloubrieu-jpl
Copy link
Member Author

Maybe but I don't think we have memory issues like that, or at least we did not in the past. For now I was more thinking one specific object is not formatted as expected by the product bean (https://github.com/NASA-PDS/registry-api-service/blob/master/src/main/java/gov/nasa/pds/api/engineering/elasticsearch/entities/EntityProduct.java). For example one field expected as String is an array or something similar.

@jordanpadams
Copy link
Member

@tloubrieu-jpl could this then maybe be related to NASA-PDS/harvest#50 ?

@jordanpadams
Copy link
Member

note: i have no idea. just string vs. array reminded me of that ticket that Al created

@nutjob4life
Copy link
Member

Whaaaaaaaaaat

@tloubrieu-jpl
Copy link
Member Author

@tdddblog @jordanpadams @al-niessner ,
Sometimes (at least once, in the pds-gamma database) the registry-refs index in elasticsearch has a document where product_lidvid is a string, see:

{
  "took": 97,
  "timed_out": false,
  "_shards": {
    "total": 1,
    "successful": 1,
    "skipped": 0,
    "failed": 0
  },
  "hits": {
    "total": {
      "value": 1,
      "relation": "eq"
    },
    "max_score": 5.941924,
    "hits": [
      {
        "_index": "registry-refs",
        "_type": "_doc",
        "_id": "urn:nasa:pds:insight_documents:document_mission::1.1::1",
        "_score": 5.941924,
        "_source": {
          "collection_lidvid": "urn:nasa:pds:insight_documents:document_mission::1.1",
          "collection_lid": "urn:nasa:pds:insight_documents:document_mission",
          "product_lidvid": "urn:nasa:pds:insight_documents:document_mission:insight_pip_final-2015_redacted_5-10-19reda::1.1",
          "product_lid": "urn:nasa:pds:insight_documents:document_mission:insight_pip_final-2015_redacted_5-10-19reda",
          "_package_id": "4dd5d54f-0a7f-4eab-a624-c86afcdb45e6"
        }
      }
    ]
  }
}

Usually it is an array.

I will update the code to support the string.

@jordanpadams
Copy link
Member

@tloubrieu-jpl @tdddblog so this appears to be directly tied to NASA-PDS/harvest#50. so do we fix in the API and then eventually harvest?

@tloubrieu-jpl
Copy link
Member Author

I am fixing that in the API now. .
i don't know if @tdddblog consider that as a bug for harvest or registry-mgr. We can discuss that during the breakout today

@tloubrieu-jpl
Copy link
Member Author

For test purpose I deployed the branch error_500_17 on pds-gamma and it works.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
B12.0 bug Something isn't working c.api s.high
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants