Story #7685
implement HTTP 1.1 caching on CN servers for nodelists
100%
Description
Metacat makes many listNodes() calls, which the CN apache server caches, but does not return any headers in the response, which would enable standards-based client-side caching. (further lessening the load on the CN).
Dave reports that the directive "CacheDetailHeader on", will do this, but it ws introduced in apache 2.3.9, so migrating to Ubuntu 14.04 may be a prerequisite (it uses Apache 2.4)
We need to implement in a test environment so we can test libclient_java implementation for correctness.
information on 14.04 caching: https://www.digitalocean.com/community/tutorials/how-to-configure-apache-content-caching-on-ubuntu-14-04
Associated revisions
refs: #7685: Added client-side HTTP/1.1 caching to default HttpClient implementation.
refs: #7685: Added client-side HTTP/1.1 caching to default HttpClient implementation.
refs #7685
implement HTTP 1.1 caching on CN servers for nodelists. added in Expires for use by clients
refs #7685
implement HTTP 1.1 caching on CN servers for nodelists. added in Expires for use by clients
refs #7685
implement HTTP 1.1 caching on CN servers for nodelists. added in Expires for use by clients
refs #7685
implement HTTP 1.1 caching on CN servers for nodelists. added in Expires for use by clients
History
#1 Updated by Dave Vieglais about 8 years ago
The defining document for HTTP 1.1 cache configuration is:
https://tools.ietf.org/html/rfc7234
Sections 2 and 3 provide succinct introductions to HTTP caching and by consequence are expected to provide an overview of caching behavior of both client and server implementations.
Essentially there are two parts to caching:
A client is able to cache content based on hints provided by the server about the expected lifetime and scope of the content
The server provides sufficient information to the client that the client is able to make a safe determination about the cacheability of the content and the expected lifetime of content within a cache.
#2 Updated by Dave Vieglais about 8 years ago
The apache config on cn-dev-ucsb-1.test.dataone.org has been manually modified to return cache information to the client. The adjustments made are:
<Location /cn/v1/node> ExpiresActive On ExpiresDefault "access plus 60 seconds" </Location>
This results in header information:
curl -s -v "https://cn-dev-ucsb-1.test.dataone.org/cn/v1/node" > /dev/null
* Trying 128.111.54.78...
* Connected to cn-dev-ucsb-1.test.dataone.org (128.111.54.78) port 443 (#0)
* TLS 1.2 connection using TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
* Server certificate: *.test.dataone.org
* Server certificate: RapidSSL SHA256 CA - G3
* Server certificate: GeoTrust Global CA
GET /cn/v1/node HTTP/1.1
Host: cn-dev-ucsb-1.test.dataone.org
User-Agent: curl/7.43.0
Accept: /< HTTP/1.1 200 OK
< Date: Tue, 22 Mar 2016 01:29:10 GMT
< Server: Apache/2.2.22 (Ubuntu)
< Content-Language: en-US
< Content-Length: 12770
< Cache-Control: max-age=60
< Expires: Tue, 22 Mar 2016 01:30:10 GMT
< Access-Control-Allow-Origin:
< Access-Control-Allow-Credentials: true
< Access-Control-Allow-Headers: Authorization, Content-Type, Location, Content-Length, x-annotator-auth-token
< Access-Control-Expose-Headers: Content-Length, Content-Type, Location
< Access-Control-Allow-Methods: POST, GET, OPTIONS, PUT, DELETE
< Vary: Accept-Encoding
< Content-Type: text/xml;charset=UTF-8
I was able to verify expected cache management behavior with the python requests and cachecontrol libraries, and that after making the changes, the client successfully retained the content and did not make requests over the wire for 60 seconds.
#3 Updated by Dave Vieglais about 8 years ago
The python script used to test the caching:
'''
Testing caching of /v1/node
'''
import time
import logging
import requests
import cachecontrol
import httplib as http_client
logging.basicConfig(level = logging.DEBUG)
http_client.HTTPConnection.debuglevel = 1
url = "https://cn-dev-ucsb-1.test.dataone.org/cn/v1/node"
session = requests.session()
cached_session = cachecontrol.CacheControl(session)
t0 = time.time()
for i in xrange(0,30):
t1 = time.time()
consume = cached_session.get(url).content
t2 = time.time()
tdelta = t1 - t0
ttime = t2 - t1
logging.info("Request %d at t+%.3f sec took %.3f seconds", i, tdelta, ttime)
time.sleep(5)
results in :
python test_cache.py
DEBUG:cachecontrol.controller:Looking up "https://cn-dev-ucsb-1.test.dataone.org/cn/v1/node" in the cache
DEBUG:cachecontrol.controller:No cache entry available
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): cn-dev-ucsb-1.test.dataone.org
send: 'GET /cn/v1/node HTTP/1.1\r\nHost: cn-dev-ucsb-1.test.dataone.org\r\nConnection: keep-alive\r\nAccept-Encoding: gzip, deflate\r\nAccept: /\r\nUser-Agent: python-requests/2.9.1\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: Date: Tue, 22 Mar 2016 01:57:01 GMT
header: Server: Apache/2.2.22 (Ubuntu)
header: Content-Language: en-US
header: Cache-Control: max-age=60
header: Expires: Tue, 22 Mar 2016 01:58:01 GMT
header: Access-Control-Allow-Origin:
header: Access-Control-Allow-Credentials: true
header: Access-Control-Allow-Headers: Authorization, Content-Type, Location, Content-Length, x-annotator-auth-token
header: Access-Control-Expose-Headers: Content-Length, Content-Type, Location
header: Access-Control-Allow-Methods: POST, GET, OPTIONS, PUT, DELETE
header: Vary: Accept-Encoding
header: Content-Encoding: gzip
header: Content-Length: 1409
header: Keep-Alive: timeout=5, max=100
header: Connection: Keep-Alive
header: Content-Type: text/xml;charset=UTF-8
DEBUG:requests.packages.urllib3.connectionpool:"GET /cn/v1/node HTTP/1.1" 200 1409
DEBUG:cachecontrol.controller:Updating cache with response from "https://cn-dev-ucsb-1.test.dataone.org/cn/v1/node"
DEBUG:cachecontrol.controller:Caching b/c date exists and max-age > 0
INFO:root:Request 0 at t+0.000 sec took 0.673 seconds
DEBUG:cachecontrol.controller:Looking up "https://cn-dev-ucsb-1.test.dataone.org/cn/v1/node" in the cache
DEBUG:cachecontrol.controller:Current age based on date: 6
DEBUG:cachecontrol.controller:Freshness lifetime from max-age: 60
DEBUG:cachecontrol.controller:The response is "fresh", returning cached response
DEBUG:cachecontrol.controller:60 > 6
INFO:root:Request 1 at t+5.674 sec took 0.004 seconds
DEBUG:cachecontrol.controller:Looking up "https://cn-dev-ucsb-1.test.dataone.org/cn/v1/node" in the cache
DEBUG:cachecontrol.controller:Current age based on date: 11
DEBUG:cachecontrol.controller:Freshness lifetime from max-age: 60
DEBUG:cachecontrol.controller:The response is "fresh", returning cached response
DEBUG:cachecontrol.controller:60 > 11
INFO:root:Request 2 at t+10.680 sec took 0.005 seconds
DEBUG:cachecontrol.controller:Looking up "https://cn-dev-ucsb-1.test.dataone.org/cn/v1/node" in the cache
DEBUG:cachecontrol.controller:Current age based on date: 16
DEBUG:cachecontrol.controller:Freshness lifetime from max-age: 60
DEBUG:cachecontrol.controller:The response is "fresh", returning cached response
DEBUG:cachecontrol.controller:60 > 16
INFO:root:Request 3 at t+15.690 sec took 0.004 seconds
...
and with cache control on the server disabled:
python test_cache.py
DEBUG:cachecontrol.controller:Looking up "https://cn-dev-ucsb-1.test.dataone.org/cn/v1/node" in the cache
DEBUG:cachecontrol.controller:No cache entry available
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): cn-dev-ucsb-1.test.dataone.org
send: 'GET /cn/v1/node HTTP/1.1\r\nHost: cn-dev-ucsb-1.test.dataone.org\r\nConnection: keep-alive\r\nAccept-Encoding: gzip, deflate\r\nAccept: /\r\nUser-Agent: python-requests/2.9.1\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: Date: Tue, 22 Mar 2016 01:58:58 GMT
header: Server: Apache/2.2.22 (Ubuntu)
header: Content-Language: en-US
header: Access-Control-Allow-Origin:
header: Access-Control-Allow-Credentials: true
header: Access-Control-Allow-Headers: Authorization, Content-Type, Location, Content-Length, x-annotator-auth-token
header: Access-Control-Expose-Headers: Content-Length, Content-Type, Location
header: Access-Control-Allow-Methods: POST, GET, OPTIONS, PUT, DELETE
header: Vary: Accept-Encoding
header: Content-Encoding: gzip
header: Content-Length: 1409
header: Keep-Alive: timeout=5, max=100
header: Connection: Keep-Alive
header: Content-Type: text/xml;charset=UTF-8
DEBUG:requests.packages.urllib3.connectionpool:"GET /cn/v1/node HTTP/1.1" 200 1409
DEBUG:cachecontrol.controller:Updating cache with response from "https://cn-dev-ucsb-1.test.dataone.org/cn/v1/node"
INFO:root:Request 0 at t+0.000 sec took 0.670 seconds
DEBUG:cachecontrol.controller:Looking up "https://cn-dev-ucsb-1.test.dataone.org/cn/v1/node" in the cache
DEBUG:cachecontrol.controller:No cache entry available
INFO:requests.packages.urllib3.connectionpool:Resetting dropped connection: cn-dev-ucsb-1.test.dataone.org
send: 'GET /cn/v1/node HTTP/1.1\r\nHost: cn-dev-ucsb-1.test.dataone.org\r\nConnection: keep-alive\r\nAccept-Encoding: gzip, deflate\r\nAccept: /\r\nUser-Agent: python-requests/2.9.1\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: Date: Tue, 22 Mar 2016 01:59:03 GMT
header: Server: Apache/2.2.22 (Ubuntu)
header: Content-Language: en-US
header: Access-Control-Allow-Origin:
header: Access-Control-Allow-Credentials: true
header: Access-Control-Allow-Headers: Authorization, Content-Type, Location, Content-Length, x-annotator-auth-token
header: Access-Control-Expose-Headers: Content-Length, Content-Type, Location
header: Access-Control-Allow-Methods: POST, GET, OPTIONS, PUT, DELETE
header: Vary: Accept-Encoding
header: Content-Encoding: gzip
header: Age: 5
header: Content-Length: 1409
header: Keep-Alive: timeout=5, max=100
header: Connection: Keep-Alive
header: Content-Type: text/xml;charset=UTF-8
DEBUG:requests.packages.urllib3.connectionpool:"GET /cn/v1/node HTTP/1.1" 200 1409
DEBUG:cachecontrol.controller:Updating cache with response from "https://cn-dev-ucsb-1.test.dataone.org/cn/v1/node"
INFO:root:Request 1 at t+5.673 sec took 0.389 seconds
#4 Updated by Rob Nahf about 8 years ago
a simple test of calling D1Client.getCN().listNodes() every 5 seconds shows the cache being hit the expected 11 times, and then the client calling the server after the 60 second expiration. Success.
20160321-19:54:43: [INFO]: selectSession: using the default certificate location [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [ERROR]: No certificate installed in expected location: /tmp/x509up_u1046 [org.dataone.client.auth.CertificateManager]
java.io.FileNotFoundException: No certificate installed in expected location: /tmp/x509up_u1046
at org.dataone.client.auth.CertificateManager.locateDefaultCertificate(CertificateManager.java:1359)
at org.dataone.client.auth.CertificateManager.getCertificateFile(CertificateManager.java:1140)
at org.dataone.client.auth.CertificateManager.(CertificateManager.java:200)
at org.dataone.client.auth.CertificateManager$CertificateManagerSingleton.(CertificateManager.java:236)
at org.dataone.client.auth.CertificateManager.getInstance(CertificateManager.java:246)
at org.dataone.client.rest.HttpMultipartRestClient.(HttpMultipartRestClient.java:199)
at org.dataone.client.rest.DefaultHttpMultipartRestClient.(DefaultHttpMultipartRestClient.java:40)
at org.dataone.client.v2.itk.D1Client.getMultipartRestClient(D1Client.java:63)
at org.dataone.client.v2.itk.D1Client.getCN(D1Client.java:220)
at org.dataone.client.rest.CachingHttpClientTest.cacheShouldReloadObjectOnExpiration(CachingHttpClientTest.java:41)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:76)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)
at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390)
at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197)
20160321-19:54:43: [INFO]: selectSession: using the default certificate location [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: Did not find a certificate for the subject specified: null [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: ...trying SSLContext protocol: TLSv1.2 [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: ...setting SSLContext with protocol: TLSv1.2 [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: creating custom TrustManager [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: loading into client truststore: java.io.FileReader@2bb9e538 [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: 0 alias CN=DataONE Test CA,DC=dataone,DC=org [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: 1 alias CN=DataONE Test Intermediate CA,DC=dataone,DC=org [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: 2 alias CN=CILogon Basic CA 1,O=CILogon,C=US,DC=cilogon,DC=org [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: 3 alias CN=CILogon OpenID CA 1,O=CILogon,C=US,DC=cilogon,DC=org [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: 4 alias CN=CILogon Silver CA 1,O=CILogon,C=US,DC=cilogon,DC=org [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: 5 alias CN=DataONE Root CA,DC=dataone,DC=org [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: 6 alias CN=DataONE Production CA,DC=dataone,DC=org [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: 7 alias CN=RapidSSL CA,O=GeoTrust\, Inc.,C=US [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [INFO]: getSSLConnectionSocketFactory: using allow-all hostname verifier [org.dataone.client.auth.CertificateManager]
20160321-19:54:43: [WARN]: Starting monitor thread [org.dataone.client.utils.HttpConnectionMonitorService]
20160321-19:54:43: [WARN]: Starting monitoring... [org.dataone.client.utils.HttpConnectionMonitorService]
20160321-19:54:43: [WARN]: registering ConnectionManager... [org.dataone.client.utils.HttpConnectionMonitorService]
************* 0. Mon Mar 21 19:54:43 MST 2016...20160321-19:54:43: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:54:43: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:54:43: [DEBUG]: Cache miss [org.apache.http.impl.client.cache.CachingExec]
20160321-19:54:43: [DEBUG]: Connection request: [route: {s}->https://cn-dev-ucsb-1.test.dataone.org:443][total kept alive: 0; route allocated: 0 of 4; total allocated: 0 of 80] [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:54:43: [DEBUG]: Connection leased: [id: 0][route: {s}->https://cn-dev-ucsb-1.test.dataone.org:443][total kept alive: 0; route allocated: 1 of 4; total allocated: 1 of 80] [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:54:43: [DEBUG]: Opening connection {s}->https://cn-dev-ucsb-1.test.dataone.org:443 [org.apache.http.impl.execchain.MainClientExec]
20160321-19:54:43: [DEBUG]: Connecting to cn-dev-ucsb-1.test.dataone.org/128.111.54.78:443 [org.apache.http.impl.conn.HttpClientConnectionOperator]
20160321-19:54:44: [DEBUG]: Connection established 192.168.1.25:63388<->128.111.54.78:443 [org.apache.http.impl.conn.HttpClientConnectionOperator]
20160321-19:54:44: [DEBUG]: Executing request GET /cn/v2/node HTTP/1.1 [org.apache.http.impl.execchain.MainClientExec]
20160321-19:54:44: [DEBUG]: Target auth state: UNCHALLENGED [org.apache.http.impl.execchain.MainClientExec]
20160321-19:54:44: [DEBUG]: Proxy auth state: UNCHALLENGED [org.apache.http.impl.execchain.MainClientExec]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> GET /cn/v2/node HTTP/1.1 [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> Host: cn-dev-ucsb-1.test.dataone.org [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> Connection: Keep-Alive [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> User-Agent: Apache-HttpClient/4.3.6 (java 1.5) [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> Accept-Encoding: gzip,deflate [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> Via: 1.1 localhost (Apache-HttpClient/4.3.6 (cache)) [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> "GET /cn/v2/node HTTP/1.1[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> "Host: cn-dev-ucsb-1.test.dataone.org[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.3.6 (java 1.5)[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> "Via: 1.1 localhost (Apache-HttpClient/4.3.6 (cache))[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 >> "[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "HTTP/1.1 200 OK[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Date: Tue, 22 Mar 2016 02:54:44 GMT[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Server: Apache/2.2.22 (Ubuntu)[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Content-Language: en-US[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Cache-Control: max-age=60[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Expires: Tue, 22 Mar 2016 02:55:44 GMT[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Access-Control-Allow-Origin: [\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Access-Control-Allow-Credentials: true[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Access-Control-Allow-Headers: Authorization, Content-Type, Location, Content-Length, x-annotator-auth-token[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Access-Control-Expose-Headers: Content-Length, Content-Type, Location[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Access-Control-Allow-Methods: POST, GET, OPTIONS, PUT, DELETE[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Vary: Accept-Encoding[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Content-Encoding: gzip[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Content-Length: 1420[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Keep-Alive: timeout=5, max=100[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Connection: Keep-Alive[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "Content-Type: text/xml;charset=UTF-8[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "[\r][\n]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << HTTP/1.1 200 OK [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Date: Tue, 22 Mar 2016 02:54:44 GMT [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Server: Apache/2.2.22 (Ubuntu) [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Content-Language: en-US [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Cache-Control: max-age=60 [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Expires: Tue, 22 Mar 2016 02:55:44 GMT [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Access-Control-Allow-Origin: [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Access-Control-Allow-Credentials: true [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Access-Control-Allow-Headers: Authorization, Content-Type, Location, Content-Length, x-annotator-auth-token [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Access-Control-Expose-Headers: Content-Length, Content-Type, Location [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Access-Control-Allow-Methods: POST, GET, OPTIONS, PUT, DELETE [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Vary: Accept-Encoding [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Content-Encoding: gzip [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Content-Length: 1420 [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Keep-Alive: timeout=5, max=100 [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Connection: Keep-Alive [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << Content-Type: text/xml;charset=UTF-8 [org.apache.http.headers]
20160321-19:54:44: [DEBUG]: Connection can be kept alive for 5000 MILLISECONDS [org.apache.http.impl.execchain.MainClientExec]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "[0x1f][0x8b][0x8][0x0][0x0][0x0][0x0][0x0][0x0][0x3]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "[0xed][0x9b]Qs[0xda]8[0x10][0xc7][0xdf][0xef]Sh[0xfc]xgc[0xc9]0[0x1e][0xe3]LK&[0xbd][0xeb][0x14][0xd2]IHo[0xee][0xa9]#l[0x5]|gK[0x8c]$H[0xe8][0xa7]?[0xc9]PB[0xc0][0x4][0xe3][0xa4])[0xcd]0[0xc3][0x83]miW[0xf2]z[0xff]?[0xaf][0xe4]$8[0xbb][0xcf]R0#\$[0x8c]v[0xc]T[0x83][0x6] 4bqBG[0x1d][0xe3]fpay[0xc6]Y[0x18][0xe8]^[0x96][0x90][0xf3][0x94][0x88]1![0x12][0xc8][0xf9][0x84]t[0xc]I[0xee][0xa5]}/R[0x3][0x8c]9[0xb9][0xed][0x18]vD[0xf5][0xa9][0xb4]c,1[0xa3][0xa4][0xa6][0xbb][0x89][0xda][0xcc][0xa9][0xe9]Ng[0xe1]oA[0x8c][0xbe][0xaa]3[0xe8]S[0x16][0x93]O[0x89][0x90]@[0xf9][0xa5][0xc2]_^[0xee][0x18]c)'[0xbe]mSQ[0xfb][0xee][0x82][0xf1][0x91]-[0x8][0x9f]%[0x11][0xb1]sw[0xb6][0xee]i[0xac][0xc]K[0xda] #[0xc][0xf4][0xa0][0x80][0x93]I[0x9a]DX[0xaa][0xe9][0xdf][0xe2]T[0x10][0x3][0x88]9[0x8d][0xc6][0x9c][0xd1][0xe4][0xdb][0xc3][0xb5][0xc5][0xfd]ET[0xb5][0xca][0xbc][0xef]t[0xa2][0x1c]$1[0xa1]2[0xb9]M[0x8][0xf][0xa7][0x9c][0xe6]7[0xe1]G[0xf4][0x9c][0xcc][0x2]{[0xad])[0xa0]8#aD[0xad]X7[0xe4]'ALD[0xc4][0x93][0x89]TA[0xe][0xdf][0xb3][0xd1]T[0x9c]?\[0x0][0x3]e[0xe5][0x80][0xe9]DM[0x9f][0xf4][0x95][0xcf].[0x9e][0xe0]a[0x92]&2![0xe2]k~Y=[0x8c]K9&[0xfc]"!i[0xc]$[0x11]2[0xb0][0xd7]][0x6]C,[0xc8][0xcd][0xd5][0xa7]P[0xc7]B[0xa8],F[0xaf][0xe9][0x9e][0x8f][0xa2][0x12][0xd1][0xc0][0xfe][0xde]7X[0x86]H[0xac][0x8e][0x80][0x9e]l[0xc7][0xe8][0xf6][0xbb][0x8c][0xab] [0xac][0xb2]BE[0xf][0xe0][0x19]NR[0xe1][0xf8][0xb5]p[0xac][0xa0]u[0xe4]4[0xce]o[0xe7]P[0x18]u[0x9f][0x80]1[0xe3]Q1[0x8c][0x95]YI[0x18][0x83][0xfe]4Sq([0xc7][0xe4]|[0xbc][0x13][0x93]v[0xc1][0xb9][0xfb]UP[0xbc]+[0xf0][0xf8][0xad][0xb0][0x91][0xf7][0x3][0xd7]s[0xbd][0xfd][0x89]0[0xea]O[0xcc]}[0xeb][0xcc][0xd5]l:r[0xe6]>[0xaa][0x80][0xb3][0x7][0xe8][0xc6][0xec][0x8e][0xee][0xc0][0xae].wf[0x1f]z[0xfd][0x2][0xea][0x8e][0xb2][0x9d][0xbb]t[0xeb][0xb0][0xfd]@(Q[0x2][0x1]=[0xa2][0xc9]Z[0xa6][0xe4]]:[0xde]&kV[0x86][0xac][0xbd]Jd[0xed]U"k[0xef]yd[0xed][0xf5][0xaf]%[0xe3][0xaa][0x14][0xad]2[0xdb][0x3][0xc0][0xba][0x9e][0xbe][0xab]|[0xc0][0x8b][0xe0][0x8b]hL[0xe2]iJ[0xc0][0x98]My[0xc7][0xf8][0xdd][0x0]Y[0x8c][0xe7][0x8b][0x83]D[0xb9][0x84][0xa6]k"h"[0xd7]t[0xa0][0xe9][0xb8]f[0x1d][0x9a]u[0xd7]l@[0xb3][0xe1][0x9a][0xae]jtU?=[0xb4][0xea]/H[0xa4][0xfa][0x1b][0xe0].wpf[0x80]9[0xc1][0xb9]K5[0x85][0x14][0xb][0xf9]'[0xe6]3[0xf5]HI[0x1c][0xa2]6[0x84][0x16]D[0xea]7[0x80][0xd0][0xcf]5[0x8][0xe1][0x1f][0xf9]Q`?[0xee][0x9c][0xdb]vY6I[0x89]$[0xcb][0xcb]e<l[0x9a][0xa8]0l[0xdd][0xfc][0x8e][0x2]_g[0xfc][0x11]iyQ+[0xed],[0x9f][0xb2][0x12][0xe5][0xd3]r[0xd9]R [0xe3]\l[0x19][0xb3][0xdc]b!g[0xc][0xe4][0xd3]Y:[0x0][0xb7][0x8c][0x83]xM[0xde][0x84][0xce][0x12]5)},[0xf6][0xe8]z5[0xd2][0xb6][0xb2][0xff][0xa3]C;Fe[0x5]M[0xaa][0xd5][0xb0][0xf0][0xf6][0x5]n[0xd7]7%[0xec][0x96][0xd1][0xb0][0x3]Q[0xd3][0x82]u[0xb][0xc1][0x81]S[0xf7]a[0xd3][0x87][0xad][0xed][0xb8]G[0xa3][0xe1]}[0x8b][0xf4]m[0x9]w[0xc7]\U l2V[0xaf][0xa9][0x8f][0xca]F[0xe8]jP[0xf1][0xee][0x7][0xca]x[0xd7][0x1b]y[0x8f][0x8e][O[0xe8][0xb8]UF[0xc7][0xad][0x97][0xd0]q[0xeb][0xa4][0xe3][0xa3][0xd6]1z[0x13][0xef]b[0x95][0xac][0xc7][0xaf][0xe3]j[0xaf]c[0xef][0x9][0x19]{ed[0xec][0xbd][0x84][0x8c][0xbd][0xe7][0xca][0xb8][0x9a] [0xab][0xac][0x88][0xab]"[0xa3][0xca]:[0xfa][0xd9][0xc8]x[0xd6]2[0xfc][0x19][0xc4])0,[0x1b][0xdb][0xca][0x9b]5;[0x8d][0xf7][0xaf][0xa7][0x8b]s[0xdf][0xeb][0x15]GQ[0xca][0xf3][0x91][0xeb][0xd7][0xdb]5[0xaf][0x8d][0x8e][0x88]s[0xde][[0xe5][0xf3][0x9][0xce]5[0xcb]p[0xae]Y[0xc4][0xb9][0x92]xk[0x9e][0xf0]v[0xc2][0xdb][0xaf][0x84]7[0xf4][0x12]x[0xf3][0xfc]z[0xbd][0xd6][0xf0]ZG[0x84][0xb7][0xe6][0x81]x[0xfb][0xa8]?[0xca][0xc]0[0x3][0x83]f[0xa3][0xf1]z[0x1f][0xa3][0xca]am[0xa0]n[0xff][0xe2][0xd3]?[0xfd][0xbe]S[0xc0][0xb6][0x8b]tNi[0xfe][0x97][0x86] [[0xec]z[0xd2]|[0xd7]s[0x1b]t[0xda][0xcd][0x1];[0xa3][0xb7][0xda][0xb1][0xa5][0xf7]G[0x9d][0xd3][0xee][0xe8]q.[0xba][0xe][0x10][0xab]c9[0xce][0x0]5|[0xd8][0xf6][0xa1][s[0xdc][0xd7][0x17][0xab]N[0xcb][0xb5]X}f[0xea]h[0x1e][0x6][0x19][0xbe][0xbf][0xcc]Et[0xad][0xd4][0x11]"[0xd8][0xaa][0xb7][0x1a][0xc8]s[0x1a][0x81][0xfd][0xb8]%[0x10][0x13][0x1c][0x91]wi[0xca][0xb4][0xb4][0xd4]R[0x12][0xb6][0xdb].BM[0xa7][0xd5]j5[0xd5],6[0x9a][0x17][0x8a],[0x18][0xaf][0x98][0x19][0xf][0x12][0xab][0xb6][0x15][0xdb][0xc7][0xe3][[0xc5][0x8e]z[0xe3][0xe5][0xa2][0x17]fGaY[0xb4][0xd6][0xba][0xcd][0x8b]/[0x8]TFF[0xc1][0xa7][0xea][0x13]2~%d[0xb8][0x16]B[0x16]j[0xe4][0x82]o[0xf9][0xf5]f[0xcd]m[0xbf][0xfe]6[0xcd][0xaf][0x81][0x8c][0x9f]F[0xc]{[0xf3][0x9f]4[0xc2][0xff][0x1]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: http-outgoing-0 << "+[0xdf][0xca][0x94]%2[0x0][0x0]" [org.apache.http.wire]
20160321-19:54:44: [DEBUG]: Connection [id: 0][route: {s}->https://cn-dev-ucsb-1.test.dataone.org:443] can be kept alive for 5.0 seconds [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:54:44: [DEBUG]: Connection released: [id: 0][route: {s}->https://cn-dev-ucsb-1.test.dataone.org:443][total kept alive: 1; route allocated: 1 of 4; total allocated: 1 of 80] [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:54:48: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:54:48: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************ 1. Mon Mar 21 19:54:49 MST 2016...20160321-19:54:49: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:54:49: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:54:49: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:54:53: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:54:53: [DEBUG]: Connection [id:0][route:{s}->https://cn-dev-ucsb-1.test.dataone.org:443][state:null] expired @ Mon Mar 21 19:54:49 MST 2016 [org.apache.http.impl.conn.CPool]
20160321-19:54:53: [DEBUG]: http-outgoing-0: Close connection [org.apache.http.impl.conn.DefaultManagedHttpClientConnection]
20160321-19:54:53: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 2. Mon Mar 21 19:54:54 MST 2016...20160321-19:54:54: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:54:54: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:54:54: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:54:58: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:54:58: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 3. Mon Mar 21 19:54:59 MST 2016...20160321-19:54:59: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:54:59: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:54:59: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:03: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:03: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 4. Mon Mar 21 19:55:04 MST 2016...20160321-19:55:04: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:55:04: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:55:04: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:08: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:08: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 5. Mon Mar 21 19:55:09 MST 2016...20160321-19:55:09: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:55:09: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:55:09: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:13: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:13: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 6. Mon Mar 21 19:55:15 MST 2016...20160321-19:55:15: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:55:15: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:55:15: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:18: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:18: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 7. Mon Mar 21 19:55:20 MST 2016...20160321-19:55:20: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:55:20: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:55:20: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:23: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:23: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 8. Mon Mar 21 19:55:25 MST 2016...20160321-19:55:25: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:55:25: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:55:25: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:28: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:28: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 9. Mon Mar 21 19:55:30 MST 2016...20160321-19:55:30: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:55:30: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:55:30: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:33: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:33: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 10. Mon Mar 21 19:55:35 MST 2016...20160321-19:55:35: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:55:35: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:55:35: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:38: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:38: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 11. Mon Mar 21 19:55:40 MST 2016...20160321-19:55:40: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:55:40: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:55:40: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:43: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:43: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 12. Mon Mar 21 19:55:45 MST 2016...20160321-19:55:45: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:55:45: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:55:45: [DEBUG]: Revalidating cache entry [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:45: [DEBUG]: Connection request: [route: {s}->https://cn-dev-ucsb-1.test.dataone.org:443][total kept alive: 0; route allocated: 0 of 4; total allocated: 0 of 80] [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:45: [DEBUG]: Connection leased: [id: 1][route: {s}->https://cn-dev-ucsb-1.test.dataone.org:443][total kept alive: 0; route allocated: 1 of 4; total allocated: 1 of 80] [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:45: [DEBUG]: Opening connection {s}->https://cn-dev-ucsb-1.test.dataone.org:443 [org.apache.http.impl.execchain.MainClientExec]
20160321-19:55:45: [DEBUG]: Connecting to cn-dev-ucsb-1.test.dataone.org/128.111.54.78:443 [org.apache.http.impl.conn.HttpClientConnectionOperator]
20160321-19:55:45: [DEBUG]: Connection established 192.168.1.25:63393<->128.111.54.78:443 [org.apache.http.impl.conn.HttpClientConnectionOperator]
20160321-19:55:45: [DEBUG]: Executing request GET /cn/v2/node HTTP/1.1 [org.apache.http.impl.execchain.MainClientExec]
20160321-19:55:45: [DEBUG]: Target auth state: UNCHALLENGED [org.apache.http.impl.execchain.MainClientExec]
20160321-19:55:45: [DEBUG]: Proxy auth state: UNCHALLENGED [org.apache.http.impl.execchain.MainClientExec]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> GET /cn/v2/node HTTP/1.1 [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> Host: cn-dev-ucsb-1.test.dataone.org [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> Connection: Keep-Alive [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> User-Agent: Apache-HttpClient/4.3.6 (java 1.5) [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> Accept-Encoding: gzip,deflate [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> Via: 1.1 localhost (Apache-HttpClient/4.3.6 (cache)) [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> "GET /cn/v2/node HTTP/1.1[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> "Host: cn-dev-ucsb-1.test.dataone.org[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> "Connection: Keep-Alive[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> "User-Agent: Apache-HttpClient/4.3.6 (java 1.5)[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> "Accept-Encoding: gzip,deflate[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> "Via: 1.1 localhost (Apache-HttpClient/4.3.6 (cache))[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 >> "[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Date: Tue, 22 Mar 2016 02:55:45 GMT[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Server: Apache/2.2.22 (Ubuntu)[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Content-Language: en-US[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Cache-Control: max-age=60[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Expires: Tue, 22 Mar 2016 02:56:45 GMT[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Access-Control-Allow-Origin: [\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Access-Control-Allow-Credentials: true[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Access-Control-Allow-Headers: Authorization, Content-Type, Location, Content-Length, x-annotator-auth-token[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Access-Control-Expose-Headers: Content-Length, Content-Type, Location[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Access-Control-Allow-Methods: POST, GET, OPTIONS, PUT, DELETE[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Vary: Accept-Encoding[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Content-Encoding: gzip[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Content-Length: 1420[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Keep-Alive: timeout=5, max=100[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Connection: Keep-Alive[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "Content-Type: text/xml;charset=UTF-8[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "[\r][\n]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << HTTP/1.1 200 OK [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Date: Tue, 22 Mar 2016 02:55:45 GMT [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Server: Apache/2.2.22 (Ubuntu) [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Content-Language: en-US [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Cache-Control: max-age=60 [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Expires: Tue, 22 Mar 2016 02:56:45 GMT [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Access-Control-Allow-Origin: [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Access-Control-Allow-Credentials: true [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Access-Control-Allow-Headers: Authorization, Content-Type, Location, Content-Length, x-annotator-auth-token [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Access-Control-Expose-Headers: Content-Length, Content-Type, Location [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Access-Control-Allow-Methods: POST, GET, OPTIONS, PUT, DELETE [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Vary: Accept-Encoding [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Content-Encoding: gzip [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Content-Length: 1420 [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Keep-Alive: timeout=5, max=100 [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Connection: Keep-Alive [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << Content-Type: text/xml;charset=UTF-8 [org.apache.http.headers]
20160321-19:55:45: [DEBUG]: Connection can be kept alive for 5000 MILLISECONDS [org.apache.http.impl.execchain.MainClientExec]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "[0x1f][0x8b][0x8][0x0][0x0][0x0][0x0][0x0][0x0][0x3]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "[0xed][0x9b]Qs[0xda]8[0x10][0xc7][0xdf][0xef]Sh[0xfc]xgc[0xc9]0[0x1e][0xe3]LK&[0xbd][0xeb][0x14][0xd2]IHo[0xee][0xa9]#l[0x5]|gK[0x8c]$H[0xe8][0xa7]?[0xc9]PB[0xc0][0x4][0xe3][0xa4])[0xcd]0[0xc3][0x83]miW[0xf2]z[0xff]?[0xaf][0xe4]$8[0xbb][0xcf]R0#\$[0x8c]v[0xc]T[0x83][0x6] 4bqBG[0x1d][0xe3]fpay[0xc6]Y[0x18][0xe8]^[0x96][0x90][0xf3][0x94][0x88]1![0x12][0xc8][0xf9][0x84]t[0xc]I[0xee][0xa5]}/R[0x3][0x8c]9[0xb9][0xed][0x18]vD[0xf5][0xa9][0xb4]c,1[0xa3][0xa4][0xa6][0xbb][0x89][0xda][0xcc][0xa9][0xe9]Ng[0xe1]oA[0x8c][0xbe][0xaa]3[0xe8]S[0x16][0x93]O[0x89][0x90]@[0xf9][0xa5][0xc2]_^[0xee][0x18]c)'[0xbe]mSQ[0xfb][0xee][0x82][0xf1][0x91]-[0x8][0x9f]%[0x11][0xb1]sw[0xb6][0xee]i[0xac][0xc]K[0xda] #[0xc][0xf4][0xa0][0x80][0x93]I[0x9a]DX[0xaa][0xe9][0xdf][0xe2]T[0x10][0x3][0x88]9[0x8d][0xc6][0x9c][0xd1][0xe4][0xdb][0xc3][0xb5][0xc5][0xfd]ET[0xb5][0xca][0xbc][0xef]t[0xa2][0x1c]$1[0xa1]2[0xb9]M[0x8][0xf][0xa7][0x9c][0xe6]7[0xe1]G[0xf4][0x9c][0xcc][0x2]{[0xad])[0xa0]8#aD[0xad]X7[0xe4]'ALD[0xc4][0x93][0x89]TA[0xe][0xdf][0xb3][0xd1]T[0x9c]?\[0x0][0x3]e[0xe5][0x80][0xe9]DM[0x9f][0xf4][0x95][0xcf].[0x9e][0xe0]a[0x92]&2![0xe2]k~Y=[0x8c]K9&[0xfc]"!i[0xc]$[0x11]2[0xb0][0xd7]][0x6]C,[0xc8][0xcd][0xd5][0xa7]P[0xc7]B[0xa8],F[0xaf][0xe9][0x9e][0x8f][0xa2][0x12][0xd1][0xc0][0xfe][0xde]7X[0x86]H[0xac][0x8e][0x80][0x9e]l[0xc7][0xe8][0xf6][0xbb][0x8c][0xab] [0xac][0xb2]BE[0xf][0xe0][0x19]NR[0xe1][0xf8][0xb5]p[0xac][0xa0]u[0xe4]4[0xce]o[0xe7]P[0x18]u[0x9f][0x80]1[0xe3]Q1[0x8c][0x95]YI[0x18][0x83][0xfe]4Sq([0xc7][0xe4]|[0xbc][0x13][0x93]v[0xc1][0xb9][0xfb]UP[0xbc]+[0xf0][0xf8][0xad][0xb0][0x91][0xf7][0x3][0xd7]s[0xbd][0xfd][0x89]0[0xea]O[0xcc]}[0xeb][0xcc][0xd5]l:r[0xe6]>[0xaa][0x80][0xb3][0x7][0xe8][0xc6][0xec][0x8e][0xee][0xc0][0xae].wf[0x1f]z[0xfd][0x2][0xea][0x8e][0xb2][0x9d][0xbb]t[0xeb][0xb0][0xfd]@(Q[0x2][0x1]=[0xa2][0xc9]Z[0xa6][0xe4]]:[0xde]&kV[0x86][0xac][0xbd]Jd[0xed]U"k[0xef]yd[0xed][0xf5][0xaf]%[0xe3][0xaa][0x14][0xad]2[0xdb][0x3][0xc0][0xba][0x9e][0xbe][0xab]|[0xc0][0x8b][0xe0][0x8b]hL[0xe2]iJ[0xc0][0x98]My[0xc7][0xf8][0xdd][0x0]Y[0x8c][0xe7][0x8b][0x83]D[0xb9][0x84][0xa6]k"h"[0xd7]t[0xa0][0xe9][0xb8]f[0x1d][0x9a]u[0xd7]l@[0xb3][0xe1][0x9a][0xae]jtU?=[0xb4][0xea]/H[0xa4][0xfa][0x1b][0xe0].wpf[0x80]9[0xc1][0xb9]K5[0x85][0x14][0xb][0xf9]'[0xe6]3[0xf5]HI[0x1c][0xa2]6[0x84][0x16]D[0xea]7[0x80][0xd0][0xcf]5[0x8][0xe1][0x1f][0xf9]Q`?[0xee][0x9c][0xdb]vY6I[0x89]$[0xcb][0xcb]e<l[0x9a][0xa8]0l[0xdd][0xfc][0x8e][0x2]_g[0xfc][0x11]iyQ+[0xed],[0x9f][0xb2][0x12][0xe5][0xd3]r[0xd9]R [0xe3]\l[0x19][0xb3][0xdc]b!g[0xc][0xe4][0xd3]Y:[0x0][0xb7][0x8c][0x83]xM[0xde][0x84][0xce][0x12]5)},[0xf6][0xe8]z5[0xd2][0xb6][0xb2][0xff][0xa3]C;Fe[0x5]M[0xaa][0xd5][0xb0][0xf0][0xf6][0x5]n[0xd7]7%[0xec][0x96][0xd1][0xb0][0x3]Q[0xd3][0x82]u[0xb][0xc1][0x81]S[0xf7]a[0xd3][0x87][0xad][0xed][0xb8]G[0xa3][0xe1]}[0x8b][0xf4]m[0x9]w[0xc7]\U l2V[0xaf][0xa9][0x8f][0xca]F[0xe8]jP[0xf1][0xee][0x7][0xca]x[0xd7][0x1b]y[0x8f][0x8e][O[0xe8][0xb8]UF[0xc7][0xad][0x97][0xd0]q[0xeb][0xa4][0xe3][0xa3][0xd6]1z[0x13][0xef]b[0x95][0xac][0xc7][0xaf][0xe3]j[0xaf]c[0xef][0x9][0x19]{ed[0xec][0xbd][0x84][0x8c][0xbd][0xe7][0xca][0xb8][0x9a] [0xab][0xac][0x88][0xab]"[0xa3][0xca]:[0xfa][0xd9][0xc8]x[0xd6]2[0xfc][0x19][0xc4])0,[0x1b][0xdb][0xca][0x9b]5;[0x8d][0xf7][0xaf][0xa7][0x8b]s[0xdf][0xeb][0x15]GQ[0xca][0xf3][0x91][0xeb][0xd7][0xdb]5[0xaf][0x8d][0x8e][0x88]s[0xde][[0xe5][0xf3][0x9][0xce]5[0xcb]p[0xae]Y[0xc4][0xb9][0x92]xk[0x9e][0xf0]v[0xc2][0xdb][0xaf][0x84]7[0xf4][0x12]x[0xf3][0xfc]z[0xbd][0xd6][0xf0]ZG[0x84][0xb7][0xe6][0x81]x[0xfb][0xa8]?[0xca][0xc]0[0x3][0x83]f[0xa3][0xf1]z[0x1f][0xa3][0xca]am[0xa0]n[0xff][0xe2][0xd3]?[0xfd][0xbe]S[0xc0][0xb6][0x8b]tNi[0xfe][0x97][0x86] [[0xec]z[0xd2]|[0xd7]s[0x1b]t[0xda][0xcd][0x1];[0xa3][0xb7][0xda][0xb1][0xa5][0xf7]G[0x9d][0xd3][0xee][0xe8]q.[0xba][0xe][0x10][0xab]c9[0xce][0x0]5|[0xd8][0xf6][0xa1][s[0xdc][0xd7][0x17][0xab]N[0xcb][0xb5]X}f[0xea]h[0x1e][0x6][0x19][0xbe][0xbf][0xcc]Et[0xad][0xd4][0x11]"[0xd8][0xaa][0xb7][0x1a][0xc8]s[0x1a][0x81][0xfd][0xb8]%[0x10][0x13][0x1c][0x91]wi[0xca][0xb4][0xb4][0xd4]R[0x12][0xb6][0xdb].BM[0xa7][0xd5]j5[0xd5],6[0x9a][0x17][0x8a],[0x18][0xaf][0x98][0x19][0xf][0x12][0xab][0xb6][0x15][0xdb][0xc7][0xe3][[0xc5][0x8e]z[0xe3][0xe5][0xa2][0x17]fGaY[0xb4][0xd6][0xba][0xcd][0x8b]/[0x8]TFF[0xc1][0xa7][0xea][0x13]2~%d[0xb8][0x16]B[0x16]j[0xe4][0x82]o[0xf9][0xf5]f[0xcd]m[0xbf][0xfe]6[0xcd][0xaf][0x81][0x8c][0x9f]F[0xc]{[0xf3][0x9f]4[0xc2][0xff][0x1]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: http-outgoing-1 << "+[0xdf][0xca][0x94]%2[0x0][0x0]" [org.apache.http.wire]
20160321-19:55:45: [DEBUG]: Connection [id: 1][route: {s}->https://cn-dev-ucsb-1.test.dataone.org:443] can be kept alive for 5.0 seconds [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:45: [DEBUG]: Connection released: [id: 1][route: {s}->https://cn-dev-ucsb-1.test.dataone.org:443][total kept alive: 1; route allocated: 1 of 4; total allocated: 1 of 80] [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:48: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:48: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************ 13. Mon Mar 21 19:55:50 MST 2016...20160321-19:55:50: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:55:50: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:55:50: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:53: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:53: [DEBUG]: Connection [id:1][route:{s}->https://cn-dev-ucsb-1.test.dataone.org:443][state:null] expired @ Mon Mar 21 19:55:50 MST 2016 [org.apache.http.impl.conn.CPool]
20160321-19:55:53: [DEBUG]: http-outgoing-1: Close connection [org.apache.http.impl.conn.DefaultManagedHttpClientConnection]
20160321-19:55:53: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
************* 14. Mon Mar 21 19:55:55 MST 2016...20160321-19:55:55: [DEBUG]: CookieSpec selected: best-match [org.apache.http.client.protocol.RequestAddCookies]
20160321-19:55:55: [DEBUG]: Auth cache not set in the context [org.apache.http.client.protocol.RequestAuthCache]
20160321-19:55:55: [DEBUG]: Cache hit [org.apache.http.impl.client.cache.CachingExec]
20160321-19:55:58: [DEBUG]: Closing expired connections [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
20160321-19:55:58: [DEBUG]: Closing connections idle longer than 30 SECONDS [org.apache.http.impl.conn.PoolingHttpClientConnectionManager]
#5 Updated by Dave Vieglais about 8 years ago
- Target version changed from CCI-2.2.0 to CCI-2.1.3
#6 Updated by Robert Waltz about 8 years ago
- % Done changed from 0 to 30
- Assignee set to Robert Waltz
- Status changed from New to In Progress
#7 Updated by Robert Waltz about 8 years ago
- Status changed from In Progress to Testing
- % Done changed from 30 to 50
#8 Updated by Dave Vieglais almost 8 years ago
- % Done changed from 50 to 100
- Status changed from Testing to Closed
