3:02 a.m.
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=40Z0PF...
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
12:49 p.m.
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=K1M5rN...
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=K1M5rN...
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(a)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=40Z0PF...
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
3:47 p.m.
For JBoss projects we usually say that per-session or per-request messages
should be logged at "TRACE" level, with "DEBUG" being used for
relatively
infrequent but detailed lifecycle messages, and "INFO" being reserved for
very infrequent messages (like a one-time "greeting" message for example).
Of course that's not absolute law, but maybe it'll help you decide.
- DML
On 10/10/2009 12:49 PM, Adrian Cole wrote:
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=K1M5rN...
<https://node1.nirvanix.com/Upload.ashx?output=json&uploadToken=K1M5rN...
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
<http://node1.nirvanix.com/206.251.254.17:443>;, endPoint=https://node1.
nirvanix.com <http://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
<http://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
<http://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
<http://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
<http://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
<http://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
<http://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
<http://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
<http://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
<http://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
<http://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
<http://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
<http://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=K1M5rN...
<https://node1.nirvanix.com/Upload.ashx?output=json&uploadToken=K1M5rN...
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(a)gmail.com
<mailto: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=40Z0PF...
<https://node1.nirvanix.com/Upload.ashx?output=json&uploadToken=40Z0PF...
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 <http://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
_______________________________________________
infinispan-dev mailing list
infinispan-dev(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/infinispan-dev
5326
days inactive
5326
days old
infinispan-dev@lists.jboss.org
2 comments
2 participants
participants (2)
-
Adrian Cole -
David M. Lloyd