Error when trying to load WMS Service request

paulkilla commented 2 years ago

Running version thredds 5.5
OS RHEL8, Java 11

When I try and load a grib2 file through the WMS service I get the following stacktrace in threddsServlet.log

2022-09-21T10:50:28.732 +1000 [ 88212][ 11] INFO - threddsServlet - Remote host: 10.10.10.10 - Request: "GET /thredds/wms/data/model/folder/filename.slv.2022091300.000.grib2?service=WMS&version=1.3.0&request=GetCapabilities HTTP/1.1" 2022-09-21T10:50:28.742 +1000 [ 88222][ 11] ERROR - uk.ac.rdg.resc.edal.wms.WmsServlet - Capabilities template has incorrect method org.apache.velocity.exception.MethodInvocationException: Invocation of method 'getLayerMetadata' in class thredds.server.wms.ThreddsWmsCatalogue threw exception java.lang.NullPointerException at templates/capabilities-1.3.0.vm[line 187, column 34] at org.apache.velocity.runtime.parser.node.ASTMethod.handleInvocationException(ASTMethod.java:243) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTMethod.execute(ASTMethod.java:187) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTReference.execute(ASTReference.java:280) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTReference.value(ASTReference.java:567) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTExpression.value(ASTExpression.java:71) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTSetDirective.render(ASTSetDirective.java:142) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:72) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.directive.VelocimacroProxy.render(VelocimacroProxy.java:216) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.directive.RuntimeMacro.render(RuntimeMacro.java:311) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.directive.RuntimeMacro.render(RuntimeMacro.java:230) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:207) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:72) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.directive.Foreach.render(Foreach.java:420) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:207) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:72) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.directive.Foreach.render(Foreach.java:420) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:207) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:342) ~[velocity-1.7.jar:1.7] at org.apache.velocity.Template.merge(Template.java:356) ~[velocity-1.7.jar:1.7] at org.apache.velocity.Template.merge(Template.java:260) ~[velocity-1.7.jar:1.7] at uk.ac.rdg.resc.edal.wms.WmsServlet.getCapabilities(WmsServlet.java:716) [edal-wms-1.5.0.6-SNAPSHOT.jar:?] at uk.ac.rdg.resc.edal.wms.WmsServlet.dispatchWmsRequest(WmsServlet.java:370) [edal-wms-1.5.0.6-SNAPSHOT.jar:?] at thredds.server.wms.ThreddsWmsServlet.dispatchWmsRequest(ThreddsWmsServlet.java:120) [classes/:5.5-SNAPSHOT] at uk.ac.rdg.resc.edal.wms.WmsServlet.doGet(WmsServlet.java:303) [edal-wms-1.5.0.6-SNAPSHOT.jar:?] at javax.servlet.http.HttpServlet.service(HttpServlet.java:635) [servlet-api.jar:?] at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) [servlet-api.jar:?] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) [catalina.jar:8.5.32] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.32] at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) [tomcat-websocket.jar:8.5.32] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.32] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.32] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327) [spring-security-web-5.6.5.jar:5.6.5] at thredds.servlet.filter.RequestBracketingLogMessageFilter.doFilter(RequestBracketingLogMessageFilter.java:50) [classes/:5.5-SNAPSHOT] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) [spring-security-web-5.6.5.jar:5.6.5] at thredds.servlet.filter.RequestQueryFilter.doFilter(RequestQueryFilter.java:90) [classes/:5.5-SNAPSHOT] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) [spring-security-web-5.6.5.jar:5.6.5] at thredds.servlet.filter.HttpHeadFilter.doFilter(HttpHeadFilter.java:47) [classes/:5.5-SNAPSHOT] at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) [spring-security-web-5.6.5.jar:5.6.5] at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:211) [spring-security-web-5.6.5.jar:5.6.5] at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:183) [spring-security-web-5.6.5.jar:5.6.5] at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354) [spring-web-5.3.20.jar:5.3.20] at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267) [spring-web-5.3.20.jar:5.3.20] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.32] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.32] at org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71) [log4j-web-2.17.1.jar:2.17.1] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) [catalina.jar:8.5.32] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) [catalina.jar:8.5.32] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) [catalina.jar:8.5.32] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [catalina.jar:8.5.32] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:493) [catalina.jar:8.5.32] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) [catalina.jar:8.5.32] at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650) [catalina.jar:8.5.32] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) [catalina.jar:8.5.32] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) [catalina.jar:8.5.32] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) [catalina.jar:8.5.32] at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:800) [tomcat-coyote.jar:8.5.32] at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) [tomcat-coyote.jar:8.5.32] at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:800) [tomcat-coyote.jar:8.5.32] at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1471) [tomcat-coyote.jar:8.5.32] at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-coyote.jar:8.5.32] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-util.jar:8.5.32] at java.lang.Thread.run(Thread.java:829) [?:?] Caused by: java.lang.NullPointerException at thredds.server.wms.config.LayerSettings.replaceNullValues(LayerSettings.java:156) ~[classes/:5.5-SNAPSHOT] at thredds.server.wms.config.WmsDetailedConfig.getSettings(WmsDetailedConfig.java:196) ~[classes/:5.5-SNAPSHOT] at thredds.server.wms.TdsEnhancedVariableMetadata.<init>(TdsEnhancedVariableMetadata.java:45) ~[classes/:5.5-SNAPSHOT] at thredds.server.wms.ThreddsWmsCatalogue.getLayerMetadata(ThreddsWmsCatalogue.java:423) ~[classes/:5.5-SNAPSHOT] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?] at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?] at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?] at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?] at org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.doInvoke(UberspectImpl.java:395) ~[velocity-1.7.jar:1.7] at org.apache.velocity.util.introspection.UberspectImpl$VelMethodImpl.invoke(UberspectImpl.java:384) ~[velocity-1.7.jar:1.7] at org.apache.velocity.runtime.parser.node.ASTMethod.execute(ASTMethod.java:173) ~[velocity-1.7.jar:1.7]

When viewing the page in a browser the XML is cut off and not complete.

The closest I have found is the following: https://github.com/Unidata/thredds/issues/1398

which mentions:

NOTE: I also tried THREDDS version 5.3. The WMS service is also broken on that version. It returns a broken (incomplete) XML document. It outputs the services, edal capabilites, then it tried to output the layers and it crashes after the "title" of the first layer. The title is No dataset title found.. Then it just stops there, with a lot of missing info and a lot of XML elements left opened (not closed, aka invalid XML). THREDDS version 5.4-SNAPSHOT is broken in the same way as 5.3, except that it actually print the title of the layer instead of No dataset title found..

I am getting the same result as the last line, 5.4-SNAPSHOT but running 5.5.

As per the resolution in that issue I have updated the schema dtd..

This is my wmsConfig.xml

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE wmsConfig SYSTEM "https://schemas.unidata.ucar.edu/thredds/dtd/ncwms/wmsConfig.dtd">
<wmsConfig>
    <global>
        <defaults>
            <allowFeatureInfo>true</allowFeatureInfo>
            <defaultColorScaleRange>-50 50</defaultColorScaleRange>
            <defaultPaletteName>psu-viridis</defaultPaletteName>
            <defaultNumColorBands>20</defaultNumColorBands>
            <logScaling>false</logScaling>
            <intervalTime>false</intervalTime>
        </defaults>
        <standardNames>
            <standardName name="sea_water_potential_temperature" units="K">
                <defaultColorScaleRange>268 308</defaultColorScaleRange>
            </standardName>
            <standardName name="sea_water_temperature" units="K">
                <defaultColorScaleRange>268 308</defaultColorScaleRange>
            </standardName>
            <standardName name="mass_concentration_of_chlorophyll_in_sea_water" units="kg m-3">
                <logScaling>true</logScaling>
            </standardName>
        </standardNames>
    </global>
    <overrides>
        <datasetPath pathSpec="testAll/20040503*_eta_211.nc">
            <pathDefaults>
                <allowFeatureInfo>false</allowFeatureInfo>
                <defaultPaletteName>x-Occam</defaultPaletteName>
            </pathDefaults>
            <variables>
                <variable id="Z_sfc">
                    <defaultColorScaleRange>0 2920</defaultColorScaleRange>
                </variable>
            </variables>
        </datasetPath>
        <datasetPath pathSpec="testAll/20040504*_eta_211.nc">
            <pathDefaults>
                <allowFeatureInfo>true</allowFeatureInfo>
                <defaultPaletteName>seq-Reds</defaultPaletteName>
            </pathDefaults>
            <variables>
                <variable id="Z_sfc">
                    <defaultColorScaleRange>0 3170</defaultColorScaleRange>
                </variable>
            </variables>
        </datasetPath>
    </overrides>
</wmsConfig>

Thanks

ethanrd commented 2 years ago

For TDS 5, you need to restart the TDS after updating the wmsConfig.dtd URL in the wmsConfig.xml file before it will fix the problem. (An update was not needed for TDS 4.6.)

paulkilla commented 2 years ago

For TDS 5, you need to restart the TDS after updating the wmsConfig.dtd URL in the wmsConfig.xml file before it will fix the problem. (An update was not needed for TDS 4.6.)

Yep I restarted tomcat after making the change.

haileyajohnson commented 2 years ago

Is it possible you have any network restrictions in place, i.e. firewalls, js blockers, etc? Are you making the request via a browser and if so, could you try a different browser as well?

paulkilla commented 2 years ago

This is running on an AWS EC2 via an ALB.

I have gone directly on to the box and curl the same URL but with localhost and get the same result. I have also stopped firewalld and performed the same curl and get the same result.

jacutlan commented 1 year ago

I've been working with @paulkilla on this same problem on and off over the past month, and made a few observations:

The cut-off XML GetCapabilities response doesn't happen when running TDS 5.0.0 beta-8, but does on any version newer than this. (I tried versions 5.1 through to 5.5)
Adjusting the DTD in wmsConfig.xml (and then restarting) didn't appear to have any effect. It looks like the old DTD url does still work, via a Redirect response. I updated it to the new URL anyway though.
The problem doesn't seem to be restricted to only GRIB2 data. I downloaded some sample .nc data from Unidata and noticed the same cutoff XML problem with that sample too

Whenever the XML response is cut off, the threddsServlet.log output always begins as @paulkilla pasted earlier

2022-09-21T10:50:28.732 +1000 [ 88212][ 11] INFO - threddsServlet - Remote host: 10.10.10.10 - Request: "GET /thredds/wms/data/model/folder/filename.slv.2022091300.000.grib2?service=WMS&version=1.3.0&request=GetCapabilities HTTP/1.1" 2022-09-21T10:50:28.742 +1000 [ 88222][ 11] ERROR - uk.ac.rdg.resc.edal.wms.WmsServlet - Capabilities template has incorrect method org.apache.velocity.exception.MethodInvocationException: Invocation of method 'getLayerMetadata' in class thredds.server.wms.ThreddsWmsCatalogue threw exception java.lang.NullPointerException at templates/capabilities-1.3.0.vm[line 187, column 34] at ...

jacutlan commented 1 year ago

Finally found a workaround for this. It seems our problem was unrelated to Thredds itself. Our Thredds servers run inside our organisation's AWS environment, and after I tried running the same Thredds server setup outside of that environment (but with the same versions of Thredds/Java/Tomcat), I discovered there were no XML errors at all - meaning it was something in our AWS environment interfering with the server activity somehow.

I compared serverStartup.log output from the server within our org's AWS setup with the output from a server outside the org, and discovered it was not loading wmsConfig.xml properly. Specifically, the log mentioned - 'unexpected end of file'. It was trying to retrieve wmsConfig.dtd from the unidata HTTPS url, but failing for some reason (presumably some setting in our AWS setup). I double checked the appropriate certificate details were in Java's trust store, but it must have been something else.

After pointing wmsConfig.xml at a local copy of the DTD file, rather than the original URL, the problem went away and we're getting full XML responses for WMS requests now.

tdrwenski commented 1 year ago

Great that you found the solution, and thanks for posting it here! Is it okay if I close this issue?

jacutlan commented 1 year ago

Yes, thanks Tara - me and @paulkilla are good with this now.

Unidata / tds

Error when trying to load WMS Service request #291