Here's more food for thought.  Is the following appropriate depth for debug logging?  One nice thing you see here is how clearly the non-blocking I/O is working by virtue of thread names:

Cheers,
-Adrian

2009-10-10 10:43:07,025 DEBUG [org.jclouds.rest.internal.RestClientProxy] (main) Converted SDNConnection.upload to POST https://node1.nirvanix.com/Upload.ashx?output=json&uploadToken=K1M5rNkJ%7EFadhqAleNG%7EBrlTx6Hn%7E
PsCrPeDiVt%7ETaubT1QF7aJ9hKFF_Q&destFolderPath=container HTTP/1.1
2009-10-10 10:43:07,029 DEBUG [org.jclouds.rest.internal.RestClientProxy] (main) Invoking upload
2009-10-10 10:43:07,213 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (pool-1-thread-1) Starting NioHttpCommandConnectionPool [ target=node1.nirvanix.com/206.251.254.17:443, endPoint=https://node1.
nirvanix.com, hashCode=333232100 ]
2009-10-10 10:43:07,431 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 18) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,431 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 17) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,431 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 23) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,432 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 19) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,432 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 13) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,432 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 20) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,432 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 16) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,432 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 22) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,433 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 15) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,433 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 14) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,433 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 24) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,433 INFO  [org.jclouds.http.httpnio.pool.NioHttpCommandConnectionPool] (I/O dispatcher 21) Opened: node1.nirvanix.com/206.251.254.17:443
2009-10-10 10:43:07,719 DEBUG [org.jclouds.http.httpnio.pool.NioHttpCommandExecutionHandler] (I/O dispatcher 18) Sending request: POST https://node1.nirvanix.com/Upload.ashx?output=json&uploadToken=K1M5rNkJ%7EFadhqAleN
G%7EBrlTx6Hn%7EPsCrPeDiVt%7ETaubT1QF7aJ9hKFF_Q&destFolderPath=container&sessionToken=95015e5e-2d47-471d-acd9-13115c4d51e3 HTTP/1.1
2009-10-10 10:43:07,871 DEBUG [org.jclouds.http.httpnio.pool.NioHttpCommandExecutionHandler] (I/O dispatcher 18) Receiving response: HTTP/1.1 200 OK
2009-10-10 10:43:07,877 DEBUG [org.jclouds.http.functions.ReturnVoidIf2xx] (pool-1-thread-2) Processing intermediate result for: org.jclouds.http.HttpResponse@fa425c
2009-10-10 10:43:07,878 DEBUG [org.jclouds.http.functions.ReturnVoidIf2xx] (pool-1-thread-2) Processed intermediate result for: org.jclouds.http.HttpResponse@fa425c




On Sat, Oct 10, 2009 at 1:02 AM, Adrian Cole <adrian.f.cole@gmail.com> wrote:
Hi, guys.

I'm polishing up jclouds for release.  I'd like some feedback on logging, especially as relates to integration with other libraries.  In this case, I'm referring to wire logging, where we trace the inputs and outputs to the cloud service into a separate log file.  Wire logging is extremely important when troubleshooting with cloud vendors, as they can read the stacks without knowing java. Wire logging is course optional, and removes redundant content logging from other parts of the code.  

The design is largely borrowed from apache hc wire logging.  It differs in implementation, where we make it asynchronous and portable across http engines.  In other words, java, nio, and whatever engines we come up with next will have identical output like below [1]. This specific logging is controlled by categories jclouds.http.headers (for headers) and jclouds.http.wire (for content).  Note that these are not org.jclouds categories on purpose, so as to avoid accidentally turning them on with wildcards.

Please let me know what you think.

Cheers,
-Adrian

[1]
2009-10-10 00:44:37,566 DEBUG [jclouds.http.headers] (pool-1-thread-2) >> POST https://node1.nirvanix.com/Upload.ashx?output=json&uploadToken=40Z0PFwy%7EGAr1UJLbfu%7E-FVSVvit%7E8jMak3CrLV%7EojZnQoyOMqjG41UXtQ&destFolde
rPath=container&sessionToken=61b0ca55-3782-44f8-bdf1-177a9d118d28 HTTP/1.1
2009-10-10 00:44:37,566 DEBUG [jclouds.http.headers] (pool-1-thread-2) >> Content-Length: 141
2009-10-10 00:44:37,566 DEBUG [jclouds.http.headers] (pool-1-thread-2) >> Content-Type: multipart/form-data; boundary=--JCLOUDS--
2009-10-10 00:44:37,751 DEBUG [jclouds.http.wire] (pool-1-thread-1) >> "----JCLOUDS--[\r][\n]"
2009-10-10 00:44:37,751 DEBUG [jclouds.http.wire] (pool-1-thread-1) >> "Content-Disposition: form-data; name="key"; filename="key"[\r][\n]"
2009-10-10 00:44:37,751 DEBUG [jclouds.http.wire] (pool-1-thread-1) >> "Content-Type: application/octet-stream[\r][\n]"
2009-10-10 00:44:37,751 DEBUG [jclouds.http.wire] (pool-1-thread-1) >> "[\r][\n]"
2009-10-10 00:44:37,751 DEBUG [jclouds.http.wire] (pool-1-thread-1) >> "value[\r][\n]"
2009-10-10 00:44:37,751 DEBUG [jclouds.http.wire] (pool-1-thread-1) >> "----JCLOUDS----[\r][\n]"
2009-10-10 00:44:37,926 DEBUG [jclouds.http.headers] (pool-1-thread-2) << HTTP/1.1 200 OK
2009-10-10 00:44:37,926 DEBUG [jclouds.http.headers] (pool-1-thread-2) << Content-Length: 152
2009-10-10 00:44:37,926 DEBUG [jclouds.http.headers] (pool-1-thread-2) << X-Powered-By: Nirvanix SDN
2009-10-10 00:44:37,926 DEBUG [jclouds.http.headers] (pool-1-thread-2) << X-Powered-By: ASP.NET
2009-10-10 00:44:37,926 DEBUG [jclouds.http.headers] (pool-1-thread-2) << Expires: -1
2009-10-10 00:44:37,926 DEBUG [jclouds.http.headers] (pool-1-thread-2) << X-AspNet-Version: 2.0.50727
2009-10-10 00:44:37,927 DEBUG [jclouds.http.headers] (pool-1-thread-2) << Date: Sat, 10 Oct 2009 07:46:25 GMT
2009-10-10 00:44:37,927 DEBUG [jclouds.http.headers] (pool-1-thread-2) << Pragma: no-cache
2009-10-10 00:44:37,927 DEBUG [jclouds.http.headers] (pool-1-thread-2) << Content-Type: text/xml; charset=utf-8
2009-10-10 00:44:37,927 DEBUG [jclouds.http.headers] (pool-1-thread-2) << Server: Nirvanix IMFS
2009-10-10 00:44:37,927 DEBUG [jclouds.http.headers] (pool-1-thread-2) << Server: Microsoft-IIS/6.0
2009-10-10 00:44:37,927 DEBUG [jclouds.http.headers] (pool-1-thread-2) << Cache-Control: no-cache