is the threddsServlet.log expected to always have a request and completed entry

[SvenDowideit]

I started an animation render, and 21 minutes later (or so the dev tools in chrome tell me), it sent the animation to the browser (yay)

but, there's no matching completed entry in my log

using thredds 4.6.11 in a container..

dow184@OA-24-MEL:/OSM/MEL/OA_EREEFS_DEV1/scratch/logs$ tail threddsServlet.log 
2018-01-03T02:13:24.314 +0000 [   1664856][     311] INFO  - threddsServlet - Request Completed - 200 - -1 - 1672
2018-01-03T02:13:24.643 +0000 [   1665185][     312] INFO  - threddsServlet - Request Completed - 200 - -1 - 1697
2018-01-03T02:13:24.690 +0000 [   1665232][     313] INFO  - threddsServlet - Request Completed - 200 - -1 - 1662
2018-01-03T02:13:29.538 +0000 [   1670080][     314] INFO  - threddsServlet - Remote host: 140.253.154.71 - Request: "GET /thredds/wms/gbr1_2.0?item=animationTimesteps&layerName=salt&start=2017-10-31T14%3A00%3A00.000Z&end=2017-12-29T14%3A00%3A00.000Z&request=GetMetadata HTTP/1.1"
2018-01-03T02:13:30.300 +0000 [   1670842][     314] INFO  - threddsServlet - Request Completed - 200 - -1 - 762
2018-01-03T02:13:34.766 +0000 [   1675308][     315] INFO  - threddsServlet - Remote host: 140.253.154.71 - Request: "GET /thredds/wms/gbr1_2.0?LAYERS=salt&ELEVATION=-0.5&TIME=2017-10-31T14:00:00.000Z/2017-12-29T14:00:00.000Z&TRANSPARENT=true&STYLES=boxfill%2Frainbow&COLORSCALERANGE=7.534%2C37.15&NUMCOLORBANDS=20&LOGSCALE=false&SERVICE=WMS&VERSION=1.1.1&REQUEST=GetMap&FORMAT=image/gif&SRS=EPSG%3A4326&BBOX=140.73252640313,-11.168904248438,147.51157120313,-5.8727754984375&WIDTH=512&HEIGHT=400 HTTP/1.1"
2018-01-03T02:34:52.791 +0000 [   2953333][     316] INFO  - threddsServlet - Remote host: 127.0.0.1 - Request: "HEAD /thredds/catalog/catalog.html HTTP/1.1"
2018-01-03T02:34:52.795 +0000 [   2953337][     316] INFO  - threddsServlet - Request Completed - 200 - 1400 - 5
2018-01-03T02:34:54.815 +0000 [   2955357][     315] INFO  - threddsServlet - Request Completed - 200 - -1 - 1280049
2018-01-03T02:34:55.530 +0000 [   2956072][     317] INFO  - threddsServlet - Remote host: 140.253.154.71 - Request: "GET /thredds/wms/gbr1_2.0?LAYERS=salt&ELEVATION=-0.5&TIME=2017-10-31T14:00:00.000Z/2017-12-29T14:00:00.000Z&TRANSPARENT=true&STYLES=boxfill%2Frainbow&COLORSCALERANGE=7.534%2C37.15&NUMCOLORBANDS=20&LOGSCALE=false&SERVICE=WMS&VERSION=1.1.1&REQUEST=GetMap&FORMAT=image/gif&SRS=EPSG%3A4326&BBOX=140.73252640313,-11.168904248438,147.51157120313,-5.8727754984375&WIDTH=512&HEIGHT=400 HTTP/1.1"

and from tomcat,

tail tomcat/localhost_access_log.2018-01-03.txt 
140.253.154.71 - - [03/Jan/2018:02:13:24 +0000] "GET /thredds/wms/gbr1_2.0?LAYERS=salt&ELEVATION=-0.5&TIME=2017-10-31T14%3A00%3A00.000Z&TRANSPARENT=true&STYLES=boxfill%2Frainbow&COLORSCALERANGE=7.534%2C37.15&NUMCOLORBANDS=20&LOGSCALE=false&SERVICE=WMS&VERSION=1.1.1&REQUEST=GetMap&FORMAT=image%2Fpng&SRS=EPSG%3A4326&BBOX=138.6151056,-15.4305072,142.004628,-12.0409848&WIDTH=256&HEIGHT=256 HTTP/1.1" 200 268
140.253.154.71 - - [03/Jan/2018:02:13:24 +0000] "GET /thredds/wms/gbr1_2.0?LAYERS=salt&ELEVATION=-0.5&TIME=2017-10-31T14%3A00%3A00.000Z&TRANSPARENT=true&STYLES=boxfill%2Frainbow&COLORSCALERANGE=7.534%2C37.15&NUMCOLORBANDS=20&LOGSCALE=false&SERVICE=WMS&VERSION=1.1.1&REQUEST=GetMap&FORMAT=image%2Fpng&SRS=EPSG%3A4326&BBOX=135.2255832,-18.8200296,138.6151056,-15.4305072&WIDTH=256&HEIGHT=256 HTTP/1.1" 200 268
140.253.154.71 - - [03/Jan/2018:02:13:24 +0000] "GET /thredds/wms/gbr1_2.0?LAYERS=salt&ELEVATION=-0.5&TIME=2017-10-31T14%3A00%3A00.000Z&TRANSPARENT=true&STYLES=boxfill%2Frainbow&COLORSCALERANGE=7.534%2C37.15&NUMCOLORBANDS=20&LOGSCALE=false&SERVICE=WMS&VERSION=1.1.1&REQUEST=GetMap&FORMAT=image%2Fpng&SRS=EPSG%3A4326&BBOX=145.3941504,-15.4305072,148.7836728,-12.0409848&WIDTH=256&HEIGHT=256 HTTP/1.1" 200 660
140.253.154.71 - - [03/Jan/2018:02:13:24 +0000] "GET /thredds/wms/gbr1_2.0?LAYERS=salt&ELEVATION=-0.5&TIME=2017-10-31T14%3A00%3A00.000Z&TRANSPARENT=true&STYLES=boxfill%2Frainbow&COLORSCALERANGE=7.534%2C37.15&NUMCOLORBANDS=20&LOGSCALE=false&SERVICE=WMS&VERSION=1.1.1&REQUEST=GetMap&FORMAT=image%2Fpng&SRS=EPSG%3A4326&BBOX=135.2255832,-15.4305072,138.6151056,-12.0409848&WIDTH=256&HEIGHT=256 HTTP/1.1" 200 268
140.253.154.71 - - [03/Jan/2018:02:13:24 +0000] "GET /thredds/wms/gbr1_2.0?LAYERS=salt&ELEVATION=-0.5&TIME=2017-10-31T14%3A00%3A00.000Z&TRANSPARENT=true&STYLES=boxfill%2Frainbow&COLORSCALERANGE=7.534%2C37.15&NUMCOLORBANDS=20&LOGSCALE=false&SERVICE=WMS&VERSION=1.1.1&REQUEST=GetMap&FORMAT=image%2Fpng&SRS=EPSG%3A4326&BBOX=148.7836728,-18.8200296,152.1731952,-15.4305072&WIDTH=256&HEIGHT=256 HTTP/1.1" 200 666
140.253.154.71 - - [03/Jan/2018:02:13:24 +0000] "GET /thredds/wms/gbr1_2.0?LAYERS=salt&ELEVATION=-0.5&TIME=2017-10-31T14%3A00%3A00.000Z&TRANSPARENT=true&STYLES=boxfill%2Frainbow&COLORSCALERANGE=7.534%2C37.15&NUMCOLORBANDS=20&LOGSCALE=false&SERVICE=WMS&VERSION=1.1.1&REQUEST=GetMap&FORMAT=image%2Fpng&SRS=EPSG%3A4326&BBOX=148.7836728,-15.4305072,152.1731952,-12.0409848&WIDTH=256&HEIGHT=256 HTTP/1.1" 200 268
140.253.154.71 - - [03/Jan/2018:02:13:30 +0000] "GET /thredds/wms/gbr1_2.0?item=animationTimesteps&layerName=salt&start=2017-10-31T14%3A00%3A00.000Z&end=2017-12-29T14%3A00%3A00.000Z&request=GetMetadata HTTP/1.1" 200 2031
127.0.0.1 - - [03/Jan/2018:02:34:52 +0000] "HEAD /thredds/catalog/catalog.html HTTP/1.1" 200 -
140.253.154.71 - - [03/Jan/2018:02:34:54 +0000] "GET /thredds/wms/gbr1_2.0?LAYERS=salt&ELEVATION=-0.5&TIME=2017-10-31T14:00:00.000Z/2017-12-29T14:00:00.000Z&TRANSPARENT=true&STYLES=boxfill%2Frainbow&COLORSCALERANGE=7.534%2C37.15&NUMCOLORBANDS=20&LOGSCALE=false&SERVICE=WMS&VERSION=1.1.1&REQUEST=GetMap&FORMAT=image/gif&SRS=EPSG%3A4326&BBOX=140.73252640313,-11.168904248438,147.51157120313,-5.8727754984375&WIDTH=512&HEIGHT=400 HTTP/1.1" 200 8245270
140.253.154.71 - - [03/Jan/2018:02:54:45 +0000] "GET /thredds/wms/gbr1_2.0?LAYERS=salt&ELEVATION=-0.5&TIME=2017-10-31T14:00:00.000Z/2017-12-29T14:00:00.000Z&TRANSPARENT=true&STYLES=boxfill%2Frainbow&COLORSCALERANGE=7.534%2C37.15&NUMCOLORBANDS=20&LOGSCALE=false&SERVICE=WMS&VERSION=1.1.1&REQUEST=GetMap&FORMAT=image/gif&SRS=EPSG%3A4326&BBOX=140.73252640313,-11.168904248438,147.51157120313,-5.8727754984375&WIDTH=512&HEIGHT=400 HTTP/1.1" 200 8245270

[cwardgar]

Hi Sven,

Yes, each HTTP request handled by the TDS results in at least two log messages:

1. a message indicating the start of the transaction; and
2. a message indicating the end of the transaction.

See https://www.unidata.ucar.edu/software/thredds/current/tds/reference/ServletLog.html

there's no matching completed entry in my log

I disagree. Are you talking about this request?

2018-01-03T02:13:34.766 +0000 [   1675308][     315] INFO  - threddsServlet - Remote host: 140.253.154.71 - Request: "GET /thredds/wms/gbr1_2.0?LAYERS=salt&ELEVATION=-0.5&TIME=2017-10-31T14:00:00.000Z/2017-12-29T14:00:00.000Z&TRANSPARENT=true&STYLES=boxfill%2Frainbow&COLORSCALERANGE=7.534%2C37.15&NUMCOLORBANDS=20&LOGSCALE=false&SERVICE=WMS&VERSION=1.1.1&REQUEST=GetMap&FORMAT=image/gif&SRS=EPSG%3A4326&BBOX=140.73252640313,-11.168904248438,147.51157120313,-5.8727754984375&WIDTH=512&HEIGHT=400 HTTP/1.1"

If so, its "Request Completed" message is:

2018-01-03T02:34:54.815 +0000 [   2955357][     315] INFO  - threddsServlet - Request Completed - 200 - -1 - 1280049

Note the request IDs (the value in the second pair of brackets) for the messages: they're both 315.