[SOLVED] Jars downloaded even if present in cache and up to date

The public knowledge pool and discussion forum of the OWS community. Do not post confidential information here!
davidt
Posts: 2
Joined: 07 Sep 2020, 16:24

[SOLVED] Jars downloaded even if present in cache and up to date

Post by davidt »

Hi,

My application needs about 100 jars (~1GB) to be downloaded.
OpenWebStart 1.2.1 is downloading them again, even if present in cache and up to date.

Here is a log extract for 1 jar. Any idea what triggers this behavior ?

Code: Select all

[ITW-CORE][2020-09-07 16:11:17.101 CEST][DEBUG][net.adoptopenjdk.icedteaweb.resources.ResourceHandler][itwpool-8-itwthread-1#390ab2b6]: Download of resource nims-auth-api.jar will start now!
[ITW-CORE][2020-09-07 16:11:17.128 CEST][DEBUG][net.adoptopenjdk.icedteaweb.resources.cache.CacheEntry][itwpool-8-itwthread-1#390ab2b6]: isCached: remote size:12805 cached size:12805 -> true
[ITW-CORE][2020-09-07 16:11:17.129 CEST][INFO ][net.adoptopenjdk.icedteaweb.resources.cache.LeastRecentlyUsedCache][itwpool-8-itwthread-1#390ab2b6]: isCached: http://xxx.com:8080/jws/jar/nims-auth-api.jar - (v: null) = true
[ITW-CORE][2020-09-07 16:11:17.198 CEST][DEBUG][net.adoptopenjdk.icedteaweb.resources.initializer.UnversionedResourceInitializer][itwpool-8-itwthread-1#390ab2b6]: needsUpdateCheck: http://xxx.com:8080/jws/jar/nims-auth-api.jar -> true
[ITW-CORE][2020-09-07 16:11:17.199 CEST][DEBUG][net.adoptopenjdk.icedteaweb.resources.initializer.UnversionedResourceInitializer][itwpool-8-itwthread-1#390ab2b6]: Candidate URLs for location=http://xxx.com:8080/jws/jar/nims-auth-api.jar version=null state=INCOMPLETE: [http://xxx.com:8080/jws/jar/nims-auth-api.jar]
[ITW-CORE][2020-09-07 16:11:17.763 CEST][DEBUG][net.adoptopenjdk.icedteaweb.resources.cache.CacheEntry][itwpool-8-itwthread-1#390ab2b6]: isCached: remote size:12805 cached size:12805 -> true
[ITW-CORE][2020-09-07 16:11:17.763 CEST][DEBUG][net.adoptopenjdk.icedteaweb.resources.cache.CacheEntry][itwpool-8-itwthread-1#390ab2b6]: http://xxx.com:8080/jws/jar/nims-auth-api.jar - version null: isCached true
[ITW-CORE][2020-09-07 16:11:17.763 CEST][DEBUG][net.adoptopenjdk.icedteaweb.resources.cache.CacheEntry][itwpool-8-itwthread-1#390ab2b6]: http://xxx.com:8080/jws/jar/nims-auth-api.jar - version null: lastModified cache:0 actual:0 -> false
[ITW-CORE][2020-09-07 16:11:17.763 CEST][INFO ][net.adoptopenjdk.icedteaweb.resources.cache.LeastRecentlyUsedCache][itwpool-8-itwthread-1#390ab2b6]: isUpToDate: http://xxx.com:8080/jws/jar/nims-auth-api.jar - (v: null) = false
[ITW-CORE][2020-09-07 16:11:17.763 CEST][DEBUG][net.adoptopenjdk.icedteaweb.resources.initializer.UnversionedResourceInitializer][itwpool-8-itwthread-1#390ab2b6]: needsUpdate: http://xxx.com:8080/jws/jar/nims-auth-api.jar -> true
[ITW-CORE][2020-09-07 16:11:17.763 CEST][DEBUG][net.adoptopenjdk.icedteaweb.resources.initializer.UnversionedResourceInitializer][itwpool-8-itwthread-1#390ab2b6]: Found best URL for location=http://xxx.com:8080/jws/jar/nims-auth-api.jar version=null state=INCOMPLETE: url:http://xxx.com:8080/jws/jar/nims-auth-api.jar; responseCode:200; location: null; version: null; lastModified: 0; contentLength: 12805;
[ITW-CORE][2020-09-07 16:11:17.763 CEST][DEBUG][net.adoptopenjdk.icedteaweb.resources.initializer.BaseResourceInitializer][itwpool-8-itwthread-1#390ab2b6]: Invalidating resource in cache: http://xxx.com:8080/jws/jar/nims-auth-api.jar / null
[ITW-CORE][2020-09-07 16:11:17.893 CEST][DEBUG][net.adoptopenjdk.icedteaweb.resources.downloader.BaseResourceDownloader][itwpool-8-itwthread-1#390ab2b6]: Will download in background: http://xxx.com:8080/jws/jar/nims-auth-api.jar
Best Regards

Janak Mulani
Posts: 170
Joined: 24 Mar 2020, 13:37

Re: Jars downloaded even if present in cache and up to date

Post by Janak Mulani »

Hi,

I just tried with OWS 1.2.1 our following test jnlp which has 10 50 Mb jars:
http://www.download-openwebstart.com/do ... nitor.jnlp

Steps:
1. Clear cache and run : download progress dialog was shown and files were downloaded
2. Run again : No download progress dialogs were shown and files were not downloaded.
Can you please try?

In your case:
- Do you see the Download Progress Dialog when you run the second time?
- Can you please check if the jars were cached after first run : itw-settings > cache > view files
- Please check itw-settings > cache that there is no cache limit and that there is sufficient space on the machine where files will be cached in directory (normally <User Home>/.cache/icedtea-web/cache)

Stephan Classen
Posts: 157
Joined: 27 Mar 2020, 09:55

Re: Jars downloaded even if present in cache and up to date

Post by Stephan Classen »

OK, lets help you debug this a little.
From your logs I take it that the application is not public. Thus you will need to do some work for us ;-)

1) Cached Info
Locate you cache directory. The default location is ${USER_HOME}/.cache/icedtea-web/cache.
In that folder there is a file named "recently_used". Open it with a text editor and find the "nims-auth-api.jar" (because this is the one from your log).
The line starts with "xx-yy.href=". The xx and yy are the names of the folder where the file is cached (relative to the "recently-used" file.
Navigate to the folder where "nims-auth-api.jar" is cached.
Besides the jar you will also find a ".info" file.
Please post the content of the file as a reply to this discussion (you can obfuscate the jnlp-path if it contains sensitive information).

2) Server Behavior
OpenWebStart uses HEAD requests to check if a resource is up to date or needs updating.
You can use either Firefox or Chrome to test the behavior of your server. To do this you need to install the extension "rested" (available for both Firefox or Chrome)
Once this is done you can open "rested" and enter the URL to the "nims-auth-api.jar" (the URL can be found in the "recently_used" file from step 1)
Then select the HEAD instead of GET for the request type and hit send.
Please post the response of the HEAD request as a reply to this discussion.

With the above information the problem can be pinpointed and a solution is most likely possible.

davidt
Posts: 2
Joined: 07 Sep 2020, 16:24

Re: Jars downloaded even if present in cache and up to date

Post by davidt »

Hi Janak, Stephan,

Thanks to your inputs, I was able to figure out the issue and to resolve it.

1. I can confirm that the cache content is correct :

Code: Select all

C:\Users\xxx\.cache\icedtea-web\cache>grep nims-auth-api.jar recently_used
 0-6.href=http\://xxx\:8080/jws/jar/nims-auth-api.jar

 C:\Users\xxx\.cache\icedtea-web\cache>ll 0\6\
 07/09/2020 17:03 215 .info
 07/09/2020 17:03 12 805 nims-auth-api.jar
 13 020 bytes in 2 files and 2 dirs 20 480 bytes allocated
 2 224 816 128 bytes free

 C:\Users\xxx\.cache\icedtea-web\cache>cat 0\6\.info
 #automatically generated - do not edit
 #Mon Sep 07 17:03:18 CEST 2020
 last-modified=0
 last-updated=1599490997411
 content-length=12805
 jnlp-path=C\:\\Users\\xxx\\Downloads\\xxx.jnlp
2. I tried using "rested" Chrome extenstion, but it gives me 403 (forbidden) for GET or 500 (internal server error)
- GET result :

Code: Select all

 403
 X-UA-Compatible: IE=Edge
 Last-Modified: Sat, 05 Sep 2020 15:59:54 GMT
 Content-Type: text/html;charset=utf-8
 Content-Language: en
 Content-Length: 1078
 Date: Tue, 08 Sep 2020 06:03:44 GMT
- HEAD result :

Code: Select all

 500
 X-UA-Compatible: IE=Edge
 Last-Modified: Sat, 05 Sep 2020 15:59:54 GMT
 Content-Type: text/html;charset=ISO-8859-1
 Transfer-Encoding: chunked
 Content-Encoding: gzip
 Vary: Accept-Encoding
 Date: Tue, 08 Sep 2020 06:03:23 GMT
 Connection: close
3. I tried using "curl" and I added the authorization token.
- GET result :

Code: Select all

 $ curl --silent --dump-header - --header "Authorization: bearer 9df7cdcc-4d47-4665-9926-b2716964e1ee" http://xxx:8080/jws/jar/nims-auth-api.jar -o /dev/null
 HTTP/1.1 200
 X-UA-Compatible: IE=Edge
 Last-Modified: Sat, 05 Sep 2020 17:59:54 CEST
 Set-Cookie: JSESSIONID=E81D3B821531FCDA87E00A58EC01DBED;path=/jws;HttpOnly
 Content-Type: application/octet-stream
 Content-Length: 12805
 Date: Tue, 08 Sep 2020 10:54:15 GMT
- HEAD result :

Code: Select all

 $ curl --head --header "Authorization: bearer 9df7cdcc-4d47-4665-9926-b2716964e1ee" http://xxx:8080/jws/jar/nims-auth-api.jar
 HTTP/1.1 200
 X-UA-Compatible: IE=Edge
 Last-Modified: Sat, 05 Sep 2020 17:59:54 CEST
 Set-Cookie: JSESSIONID=7DCFAF3AF2A3CB17576AF6F9EE5B4FD6;path=/jws;HttpOnly
 Content-Type: application/octet-stream
 Content-Length: 12805
 Date: Tue, 08 Sep 2020 10:48:53 GMT
I got the authorization token from jnlp file :

Code: Select all

<property name="http.agent" value="_access=9df7cdcc-4d47-4665-9926-b2716964e1ee"/>
Here is the stack-trace to retrieve the Last-Modified value from response header :

Code: Select all

Daemon Thread [itwpool-3-itwthread-1] (Suspended)
 HttpURLConnection(HttpURLConnection).getHeaderFieldDate(String, long) line: 552
 HttpURLConnection(URLConnection).getLastModified() line: 559 [local variables unavailable]
 CloseableHttpConnection(CloseableConnection).getLastModified() line: 95
 UnversionedResourceDownloader(BaseResourceDownloader).getDownloadDetails(CloseableConnection) line: 150
 UnversionedResourceDownloader(BaseResourceDownloader).tryDownloading(URL) line: 89
 UnversionedResourceDownloader(BaseResourceDownloader).lambda$downloadFrom$1(CompletableFuture, URL) line: 79
 1930199040.run() line: not available
 ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) line: 1149
 ThreadPoolExecutor$Worker.run() line: 624
 Thread.run() line: 748
The "Last-Modified:" header value is "Sat, 05 Sep 2020 17:59:54 CEST" : as "GMT" is not present, the java.net.HttpURLConnection.getHeaderFieldDate code adds " GMT", generating an exception in Date.parse call, hence a lastModified=0 :

Code: Select all

public long getHeaderFieldDate(String name, long Default) {
 String dateString = getHeaderField(name);
 try {
 if (dateString.indexOf("GMT") == -1) {
 dateString = dateString+" GMT";
 }
 return Date.parse(dateString);
 } catch (Exception e) {
 }
 return Default;
 }
According to https://tools.ietf.org/html/rfc1945#section-3.3, Last-Modified is a HTTP Date :
All HTTP/1.0 date/time stamps must be represented in Universal Time (UT), also known as Greenwich Mean Time (GMT), without exception.

So the value coming from my tomcat servlet (with CEST format) is not correct.

It seems that apache-httpclient is better handling CEST format, as its PATTERN_RFC1123 = "EEE, dd MMM yyyy HH:mm:ss zzz" supports GMT and non-GMT timezones :
https://jar-download.com/artifacts/org. ... Utils.java

Anyway, I fixed our code and it is now working as expected :

Code: Select all

$ curl --head --header "Authorization: bearer 5fdda629-3533-48d6-b960-1efaf53bfa89" http://xxx:8080/jws/jar/nims-auth-api.jar
HTTP/1.1 200
X-UA-Compatible: IE=Edge
Last-Modified: Sat, 05 Sep 2020 15:59:54 GMT
Set-Cookie: JSESSIONID=A4BCC5A7E31948833A73BDD6059D5CB5;path=/jws;HttpOnly
Content-Type: application/octet-stream
Content-Length: 12805
Date: Tue, 08 Sep 2020 16:25:37 GMT


I also wanted to find out why there was no issue with JWS and I found out in viewtopic.php?f=21&t=164 the following explanation :
OWS if sending a 'simple' HEAD, while JWS if sending a GET with "If-Modified-Since".
The result is different : OWS gets some info about the resources and an HTTP 200 - OK , while JWS gets a laconic HTTP 304 : "Not Modified" (and that's indeed only what we need.


Would you evaluate the possibility to use GET with "If-Modified-Since" instead of "HEAD" ?

Another small note :
In net.adoptopenjdk.icedteaweb.resources.cache.CacheEntry.isCurrent, the criteria to use a cached jar is :

Code: Select all

final boolean isCurrent = lastModified > 0 && lastModified <= cachedModified;
But in HttpServlet.service, it is rounded to nearest second :

Code: Select all

                if (ifModifiedSince < (lastModified / 1000 * 1000)) {
                    // If the servlet mod time is later, call doGet()
                    // Round down to the nearest second for a proper compare
                    // A ifModifiedSince of -1 will always be less
                    maybeSetLastModified(resp, lastModified);
                    doGet(req, resp);
                } else {
                    resp.setStatus(HttpServletResponse.SC_NOT_MODIFIED);
                }

Final note: our application startup time is better with OWS (15s) compared to JWS (19s) !
Congratulations !

Stephan Classen
Posts: 157
Joined: 27 Mar 2020, 09:55

Re: Jars downloaded even if present in cache and up to date

Post by Stephan Classen »

Great to hear that your problem has been solved.

We currently do the HEAD request not only for validating the cache entry but OWS is often trying multiple URLs to see which is the best to use for downloading.
An example of this is that OWS will try https first even if http is specified in an URL. Also there are some quirks introduced by the original JavaWebStart which OWS is trying to mimic (see: https://docs.oracle.com/javase/tutorial ... hecks.html).
In some cases we end up with 4 or 6 URLs to try per resource. Whit the HEAD request we can do all of them in parallel and then choose the best URL from the results.

Post Reply