Hi Sean, yes, that looks to be correct. I went ahead and disabled cache for
NetCDF and RandomAccess and now the files do not stay open. We'll see if that
prevents server errors going forward when NCSS requests hit those surface files.
I've attached the stack trace associated with the 500 server errors.
Thanks,
Kevin
_____________________________________________
Kevin Tyle, M.S.; Manager of Departmental Computing
NSF XSEDE Campus Champion
Dept. of Atmospheric & Environmental Sciences
University at Albany
Earth Science 228, 1400 Washington Avenue
Albany, NY 12222
Email: ktyle@xxxxxxxxxx
Phone: 518-442-4578
_____________________________________________
________________________________
From: Sean Arms <sarms@xxxxxxxx>
Sent: Thursday, May 7, 2020 7:10 PM
To: Tyle, Kevin R <ktyle@xxxxxxxxxx>
Cc: THREDDS community <thredds@xxxxxxxxxxxxxxxx>
Subject: Re: [thredds] THREDDS/NCSS/Open Files
Greetings Kevin,
I'm think what you are seeing is this:
https://github.com/Unidata/thredds/issues/820
We have a few caches and they don't always play nice (and when they
don't, they go nuclear). The whole TDS cache infrastructure needs
reworked. You could try disabling those caches as Christian suggested
in the github issue to see if that stops the issues (it's a
grass-and-dirt covered band-aid and more of a troubleshooting step,
not a fix). When you were seeing the 500s, what did the stacktraces
associated with them look like?
Cheers,
Sean
On Wed, May 6, 2020 at 3:23 PM Tyle, Kevin R <ktyle@xxxxxxxxxx> wrote:
>
> Hi Don, yes, it's indeed a very useful feature ...thanks for helping to make
> it possible!
>
> I can further add that even closing the Python notebook that originally
> accessed the GEMPAK file will not cause the file handles listed in lsof to
> close. Only a restart of THREDDS will accomplish that.
>
> So yes, Sean, if you can check into this hopefully a solution can be
> forthcoming.
>
> Cheers,
>
> Kevin
>
> _____________________________________________
> Kevin Tyle, M.S.; Manager of Departmental Computing
> NSF XSEDE Campus Champion
> Dept. of Atmospheric & Environmental Sciences
> University at Albany
> Earth Science 228, 1400 Washington Avenue
> Albany, NY 12222
> Email: ktyle@xxxxxxxxxx
> Phone: 518-442-4578
> _____________________________________________
>
> -----Original Message-----
> From: thredds <thredds-bounces@xxxxxxxxxxxxxxxx> On Behalf Of Don Murray via
> thredds
> Sent: Wednesday, May 6, 2020 3:55 PM
> To: thredds@xxxxxxxxxxxxxxxx
> Subject: Re: [thredds] THREDDS/NCSS/Open Files
>
> Hi Kevin-
>
> Since I wrote the GEMPAK IOSP over 10 years ago, my guess is that it might be
> missing some dataset close method. The netCDF-java IOSP API changed in that
> time, so it might just be a matter of adding some close methods to the IOSP
> classes. Sean would know more. Glad to know that you still find that useful.
>
> Don
>
> On 5/6/20 1:10 PM, Tyle, Kevin R wrote:
> > Hi,
> >
> > Our THREDDS server (http://thredds.atmos.albany.edu:8080/thredds , still
> > running 4.6.13 at this time) serves both a current-week and longer term
> > archive of GEMPAK-formatted METAR files as Feature Collections. Very
> > nicely, THREDDS invokes netcdf-java to handle the conversion of GEMPAK
> > to NetCDF. The archive is accessed especially frequently at this time of
> > the year, when my co-instructor and I have the students do a case study
> > of their choice and use MetPy and Siphon to access, subset, and display
> > surface maps and meteograms for their event of interest.
> >
> > Typically, I soon run into issues where the THREDDS server fails with
> > 500 server errors when an arbitrary GEMPAK surface file gets accessed
> > via NCSS. I have traced this to our NCSS and Random Access caches having
> > max values set too low.
> >
> > I see messages in the content/thredds/logs/cache.log file that look like
> > this:
> >
> > [2020-05-06T00:25:01.089+0000] FileCache NetcdfFileCache cleanup
> > couldnt remove enough to keep under the maximum= 150 due to locked
> > files; currently at = 905
> >
> > [2020-05-06T00:25:44.105+0000] FileCache RandomAccessFile cleanup
> > couldnt remove enough to keep under the maximum= 500 due to locked
> > files; currently at = 905
> >
> > No prob, I have upped these limits now. But those "locked files"
> > references made me do some poking around on the machine which is running
> > THREDDS. I notice that when I run the *lsof* command and grep for one of
> > the GEMPAK files that has been accessed, I see a really large # of matches.
> >
> > For example, just now I picked one particular file, ran my Jupyter
> > notebook on it that queries and returns the subsetted data via Siphon,
> > and then ran *lsof *and grepped specifically for that one file.
> >
> > Not surprisingly, it was listed in the *lsof* output. But surprisingly,
> > *lsof *had it listed 89 times! Why might that be the case?
> >
> > Multiply this by a dozen or so students and co-instructors, and 1-4
> > individual GEMPAK files per case, and now I'm seeing why I consistently
> > run into issues, particularly with these types of datasets. Once the
> > notebook instance is closed, the open files disappear from *lsof*, but
> > often times students (and even I) forget to close and halt their Jupyter
> > notebooks.
> >
> > Curiously, when I look into my content/thredds/cache/ncss directory, I
> > don't see anything.
> >
> > So my two questions are:
> >
> > 1. Why does *lsof* return such a large number of duplicate references
> > for a single file that's being accessed via NCSS?
> > 2. Why do I not see files appear in the *cache* directory, even when
> > there are clearly instances when the cache scouring script detects them?
> >
> > Thanks,
> >
> > Kevin
> >
> > _____________________________________________
> >
> > Kevin Tyle, M.S.; Manager of Departmental Computing
> >
> > NSF XSEDE Campus Champion
> >
> > Dept. of Atmospheric & Environmental Sciences
> >
> > University at Albany
> >
> > Earth Science 228, 1400 Washington Avenue
> >
> > Albany, NY 12222
> >
> > Email: ktyle@xxxxxxxxxx <mailto:ktyle@xxxxxxxxxx>
> >
> > Phone: 518-442-4578
> >
> > _____________________________________________
> >
> >
> > _______________________________________________
> > NOTE: All exchanges posted to Unidata maintained email lists are
> > recorded in the Unidata inquiry tracking system and made publicly
> > available through the web. Users who post to any of the lists we
> > maintain are reminded to remove any personal information that they
> > do not want to be made public.
> >
> >
> > thredds mailing list
> > thredds@xxxxxxxxxxxxxxxx
> > For list information or to unsubscribe, visit:
> > https://www.unidata.ucar.edu/mailing_lists/
> >
>
> --
> Don Murray
> NOAA/PSL and CU-CIRES
> 303-497-3596
> https://www.psl.noaa.gov/people/don.murray/
>
> _______________________________________________
> NOTE: All exchanges posted to Unidata maintained email lists are
> recorded in the Unidata inquiry tracking system and made publicly
> available through the web. Users who post to any of the lists we
> maintain are reminded to remove any personal information that they
> do not want to be made public.
>
>
> thredds mailing list
> thredds@xxxxxxxxxxxxxxxx
> For list information or to unsubscribe, visit:
> https://www.unidata.ucar.edu/mailing_lists/
>
> _______________________________________________
> NOTE: All exchanges posted to Unidata maintained email lists are
> recorded in the Unidata inquiry tracking system and made publicly
> available through the web. Users who post to any of the lists we
> maintain are reminded to remove any personal information that they
> do not want to be made public.
>
>
> thredds mailing list
> thredds@xxxxxxxxxxxxxxxx
> For list information or to unsubscribe, visit:
> https://www.unidata.ucar.edu/mailing_lists/
2020-05-05T17:52:43.771 +0000 [ 16855167][ 396] ERROR -
thredds.server.ncss.controller.AbstractNcssController - Uncaught exception
java.lang.NullPointerException: null
at ucar.unidata.io.RandomAccessFile.read_(RandomAccessFile.java:762)
~[cdm-4.6.13.jar:4.6.13]
at
ucar.unidata.io.RandomAccessFile.readBuffer(RandomAccessFile.java:522)
~[cdm-4.6.13.jar:4.6.13]
at ucar.unidata.io.RandomAccessFile.seek(RandomAccessFile.java:510)
~[cdm-4.6.13.jar:4.6.13]
at
ucar.nc2.iosp.gempak.GempakFileReader.DM_RINT(GempakFileReader.java:1376)
~[visadCdm-4.6.13.jar:4.6.13]
at
ucar.nc2.iosp.gempak.GempakFileReader.DM_RDTR(GempakFileReader.java:1579)
~[visadCdm-4.6.13.jar:4.6.13]
at
ucar.nc2.iosp.gempak.GempakFileReader.DM_RDTR(GempakFileReader.java:1536)
~[visadCdm-4.6.13.jar:4.6.13]
at
ucar.nc2.iosp.gempak.GempakSurfaceIOSP.readStandardData(GempakSurfaceIOSP.java:208)
~[visadCdm-4.6.13.jar:4.6.13]
at
ucar.nc2.iosp.gempak.GempakSurfaceIOSP.readData(GempakSurfaceIOSP.java:143)
~[visadCdm-4.6.13.jar:4.6.13]
at ucar.nc2.NetcdfFile.readData(NetcdfFile.java:2026)
~[cdm-4.6.13.jar:4.6.13]
at ucar.nc2.Variable.reallyRead(Variable.java:913)
~[cdm-4.6.13.jar:4.6.13]
at ucar.nc2.Variable._read(Variable.java:898) ~[cdm-4.6.13.jar:4.6.13]
at ucar.nc2.Variable.read(Variable.java:709) ~[cdm-4.6.13.jar:4.6.13]
at ucar.nc2.dataset.StructureDS.reallyRead(StructureDS.java:253)
~[cdm-4.6.13.jar:4.6.13]
at ucar.nc2.Variable._read(Variable.java:898) ~[cdm-4.6.13.jar:4.6.13]
at ucar.nc2.Variable.read(Variable.java:709) ~[cdm-4.6.13.jar:4.6.13]
at
ucar.nc2.ft.point.standard.Table$TableMultidimStructure.getStructureDataIterator(Table.java:997)
~[cdm-4.6.13.jar:4.6.13]
at
ucar.nc2.ft.point.standard.NestedTable.getLeafFeatureDataIterator(NestedTable.java:676)
~[cdm-4.6.13.jar:4.6.13]
at
ucar.nc2.ft.point.standard.StandardStationCollectionImpl$StandardStationFeatureImpl.getPointFeatureIterator(StandardStationCollectionImpl.java:120)
~[cdm-4.6.13.jar:4.6.13]
at
ucar.nc2.ft.point.collection.CompositeStationCollection$CompositeStationFeature$CompositeStationFeatureIterator.getNextIterator(CompositeStationCollection.java:326)
~[cdm-4.6.13.jar:4.6.13]
at
ucar.nc2.ft.point.collection.CompositeStationCollection$CompositeStationFeature$CompositeStationFeatureIterator.hasNext(CompositeStationCollection.java:331)
~[cdm-4.6.13.jar:4.6.13]
at
ucar.nc2.ft.point.PointIteratorFiltered.nextFilteredDataPoint(PointIteratorFiltered.java:97)
~[cdm-4.6.13.jar:4.6.13]
at
ucar.nc2.ft.point.PointIteratorFiltered.hasNext(PointIteratorFiltered.java:73)
~[cdm-4.6.13.jar:4.6.13]
at
ucar.nc2.ft.point.PointCollectionImpl.hasNext(PointCollectionImpl.java:128)
~[cdm-4.6.13.jar:4.6.13]
at
thredds.server.ncss.view.dsg.station.AbstractStationSubsetWriter.writeStationTimeSeriesFeature(AbstractStationSubsetWriter.java:96)
~[classes/:4.6.13]
at
thredds.server.ncss.view.dsg.station.AbstractStationSubsetWriter.write(AbstractStationSubsetWriter.java:83)
~[classes/:4.6.13]
at
thredds.server.ncss.view.dsg.AbstractDsgSubsetWriter.respond(AbstractDsgSubsetWriter.java:40)
~[classes/:4.6.13]
at
thredds.server.ncss.controller.NcssController.handleRequestDsg(NcssController.java:232)
~[classes/:4.6.13]
at
thredds.server.ncss.controller.NcssController.handleRequest(NcssController.java:147)
~[classes/:4.6.13]
at sun.reflect.GeneratedMethodAccessor145.invoke(Unknown Source) ~[?:?]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[?:1.8.0_241]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_241]
at
org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
~[spring-web-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)
~[spring-web-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
~[spring-webmvc-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:849)
~[spring-webmvc-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:760)
~[spring-webmvc-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
~[spring-webmvc-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
[spring-webmvc-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
[spring-webmvc-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
[spring-webmvc-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
[spring-webmvc-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:634)
[servlet-api.jar:?]
at
org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
[spring-webmvc-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
[servlet-api.jar:?]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
[catalina.jar:8.5.53]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
[catalina.jar:8.5.53]
at
thredds.servlet.filter.RequestQueryFilter.doFilter(RequestQueryFilter.java:118)
[classes/:4.6.13]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
[catalina.jar:8.5.53]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
[catalina.jar:8.5.53]
at
org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
[tomcat-websocket.jar:8.5.53]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
[catalina.jar:8.5.53]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
[catalina.jar:8.5.53]
at
thredds.servlet.filter.RequestCORSFilter.doFilterInternal(RequestCORSFilter.java:49)
[classes/:4.6.13]
at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
[spring-web-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:347)
[spring-web-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:263)
[spring-web-4.3.20.RELEASE.jar:4.3.20.RELEASE]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
[catalina.jar:8.5.53]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
[catalina.jar:8.5.53]
at
thredds.servlet.filter.RequestPathFilter.doFilter(RequestPathFilter.java:94)
[classes/:4.6.13]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
[catalina.jar:8.5.53]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
[catalina.jar:8.5.53]
at
thredds.server.RequestBracketingLogMessageFilter.doFilter(RequestBracketingLogMessageFilter.java:81)
[classes/:4.6.13]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
[catalina.jar:8.5.53]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
[catalina.jar:8.5.53]
at
org.apache.logging.log4j.web.Log4jServletFilter.doFilter(Log4jServletFilter.java:71)
[log4j-web-2.8.2.jar:2.8.2]
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
[catalina.jar:8.5.53]
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
[catalina.jar:8.5.53]
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:200)
[catalina.jar:8.5.53]
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
[catalina.jar:8.5.53]
at
org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:543)
[catalina.jar:8.5.53]
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
[catalina.jar:8.5.53]
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
[catalina.jar:8.5.53]
at
org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:688)
[catalina.jar:8.5.53]
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
[catalina.jar:8.5.53]
at
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
[catalina.jar:8.5.53]
at
org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:615)
[tomcat-coyote.jar:8.5.53]
at
org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
[tomcat-coyote.jar:8.5.53]
at
org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:818)
[tomcat-coyote.jar:8.5.53]
at
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1623)
[tomcat-coyote.jar:8.5.53]
at
org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
[tomcat-coyote.jar:8.5.53]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[?:1.8.0_241]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[?:1.8.0_241]
at
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
[tomcat-util.jar:8.5.53]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_241]
2020-05-05T17:52:43.818 +0000 [ 16855214][ 396] INFO - threddsServlet -
Request Completed - 500 - -1 - 3156
