[Checkins] SVN: zc.zservertracelog/trunk/ merge -r98286:HEAD svn+ssh://svn.zope.org/repos/main/zc.zservertracelog/branches/jackie-time-resolution
Alex Chapman
achapman at zope.com
Wed Mar 25 11:06:13 EDT 2009
Log message for revision 98366:
merge -r98286:HEAD svn+ssh://svn.zope.org/repos/main/zc.zservertracelog/branches/jackie-time-resolution
Changed:
U zc.zservertracelog/trunk/CHANGES.txt
U zc.zservertracelog/trunk/README.txt
U zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt
U zc.zservertracelog/trunk/src/zc/zservertracelog/tests.py
U zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py
-=-
Modified: zc.zservertracelog/trunk/CHANGES.txt
===================================================================
--- zc.zservertracelog/trunk/CHANGES.txt 2009-03-25 14:39:52 UTC (rev 98365)
+++ zc.zservertracelog/trunk/CHANGES.txt 2009-03-25 15:06:13 UTC (rev 98366)
@@ -2,6 +2,12 @@
Changes
=========
+1.2.0 (unreleased)
+------------------
+
+- sub-second resolution in timestamps
+
+
1.1.1 (2008-11-21)
------------------
Modified: zc.zservertracelog/trunk/README.txt
===================================================================
--- zc.zservertracelog/trunk/README.txt 2009-03-25 14:39:52 UTC (rev 98365)
+++ zc.zservertracelog/trunk/README.txt 2009-03-25 15:06:13 UTC (rev 98366)
@@ -13,37 +13,37 @@
- Request begins:
- B -1214390740 2007-04-27T20:16:55 GET /
+ B -1214390740 2007-04-27T20:16:55.582940 GET /
Includes the request method and path.
- Got request input:
- I -1214390740 2007-04-27T20:16:55 0
+ I -1214390740 2007-04-27T20:16:55.605791 0
Includes the request content length.
- Entered application thread:
- C -1214390740 2007-04-27T20:16:55
+ C -1214390740 2007-04-27T20:16:55.703829
- Application done:
- A -1223774356 2007-04-27T20:16:55 500 84
+ A -1223774356 2007-04-27T20:16:55.890371 500 84
Includes the response content length.
- Request done:
- E -1223774356 2007-04-27T20:16:55
+ E -1223774356 2007-04-27T20:16:55.913855
In addition, application startup is logged with an 'S' record:
- S 0 2007-04-27T20:24:29
+ S 0 2007-04-27T20:24:29.013922
Tracelog extension records are prefixed with a '-':
- - -1223774356 2008-09-12T15:51:05 zc.example.extension message
+ - -1223774356 2008-09-12T15:51:05.559302 zc.example.extension message
To create a trace log, include the zc.zservertracelog package in your
site ZCML configuration. Also, define a logger section in zope.conf::
Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt 2009-03-25 14:39:52 UTC (rev 98365)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt 2009-03-25 15:06:13 UTC (rev 98366)
@@ -30,7 +30,7 @@
>>> zc.zservertracelog.tracelog.started(
... zope.app.appsetup.interfaces.ProcessStarting())
- S 0 2008-08-26T11:55:00
+ S 0 2008-08-26 11:55:00.000000
Tracing Applications
@@ -63,11 +63,11 @@
... """
>>> invokeRequest(req1)
- B 23423600 2008-08-27T10:54:08 GET /test-req1
- I 23423600 2008-08-27T10:54:08 0
- C 23423600 2008-08-27T10:54:08
- A 23423600 2008-08-27T10:54:08 200 ?
- E 23423600 2008-08-27T10:54:08
+ B 23423600 2008-08-27 10:54:08.000000 GET /test-req1
+ I 23423600 2008-08-27 10:54:08.000000 0
+ C 23423600 2008-08-27 10:54:08.000000
+ A 23423600 2008-08-27 10:54:08.000000 200 ?
+ E 23423600 2008-08-27 10:54:08.000000
Application Errors
@@ -87,11 +87,11 @@
... invokeRequest(req1)
... except:
... pass
- B 21663984 2008-09-02T11:19:26 GET /test-req1
- I 21663984 2008-09-02T11:19:26 0
- C 21663984 2008-09-02T11:19:26
- A 21663984 2008-09-02T11:19:26 Error: oh noes!
- E 21663984 2008-09-02T11:19:26
+ B 21663984 2008-09-02 11:19:26.000000 GET /test-req1
+ I 21663984 2008-09-02 11:19:26.000000 0
+ C 21663984 2008-09-02 11:19:26.000000
+ A 21663984 2008-09-02 11:19:26.000000 Error: oh noes!
+ E 21663984 2008-09-02 11:19:26.000000
Response Errors
@@ -112,11 +112,11 @@
... invokeRequest(req1)
... except:
... pass
- B 21651664 2008-09-02T13:59:02 GET /test-req1
- I 21651664 2008-09-02T13:59:02 0
- C 21651664 2008-09-02T13:59:02
- A 21651664 2008-09-02T13:59:02 200 ?
- E 21651664 2008-09-02T13:59:02 Error: iteration over non-sequence
+ B 21651664 2008-09-02 13:59:02.000000 GET /test-req1
+ I 21651664 2008-09-02 13:59:02.000000 0
+ C 21651664 2008-09-02 13:59:02.000000
+ A 21651664 2008-09-02 13:59:02.000000 200 ?
+ E 21651664 2008-09-02 13:59:02.000000 Error: iteration over non-sequence
Let's clean up before moving on.
@@ -136,11 +136,11 @@
... """
>>> invokeRequest(req2)
- B 21598352 2008-09-12T11:40:27 GET /test-req2/\nohnoes/
- I 21598352 2008-09-12T11:40:27 0
- C 21598352 2008-09-12T11:40:27
- A 21598352 2008-09-12T11:40:27 200 ?
- E 21598352 2008-09-12T11:40:27
+ B 21598352 2008-09-12 11:40:27.000000 GET /test-req2/\nohnoes/
+ I 21598352 2008-09-12 11:40:27.000000 0
+ C 21598352 2008-09-12 11:40:27.000000
+ A 21598352 2008-09-12 11:40:27.000000 200 ?
+ E 21598352 2008-09-12 11:40:27.000000
Request Query Strings
@@ -155,11 +155,11 @@
... """
>>> invokeRequest(req3)
- B 21598352 2008-09-12T11:40:27 GET /test-req3/?creature=unicorn
- I 21598352 2008-09-12T11:40:27 0
- C 21598352 2008-09-12T11:40:27
- A 21598352 2008-09-12T11:40:27 200 ?
- E 21598352 2008-09-12T11:40:27
+ B 21598352 2008-09-12 11:40:27.000000 GET /test-req3/?creature=unicorn
+ I 21598352 2008-09-12 11:40:27.000000 0
+ C 21598352 2008-09-12 11:40:27.000000
+ A 21598352 2008-09-12 11:40:27.000000 200 ?
+ E 21598352 2008-09-12 11:40:27.000000
Empty query strings are also preserved.
@@ -170,11 +170,11 @@
... """
>>> invokeRequest(req4)
- B 21598352 2008-09-12T11:40:27 GET /test-req4/?
- I 21598352 2008-09-12T11:40:27 0
- C 21598352 2008-09-12T11:40:27
- A 21598352 2008-09-12T11:40:27 200 ?
- E 21598352 2008-09-12T11:40:27
+ B 21598352 2008-09-12 11:40:27.000000 GET /test-req4/?
+ I 21598352 2008-09-12 11:40:27.000000 0
+ C 21598352 2008-09-12 11:40:27.000000
+ A 21598352 2008-09-12 11:40:27.000000 200 ?
+ E 21598352 2008-09-12 11:40:27.000000
Adding Additional Entries to the Trace Log
@@ -192,9 +192,9 @@
>>> faux_app.app_hook = noisy_app
>>> invokeRequest(req1)
- B 21569456 2008-09-12T15:51:05 GET /test-req1
- I 21569456 2008-09-12T15:51:05 0
- C 21569456 2008-09-12T15:51:05
- - 21569456 2008-09-12T15:51:05 beep! beep!
- A 21569456 2008-09-12T15:51:05 200 ?
- E 21569456 2008-09-12T15:51:05
+ B 21569456 2008-09-12 15:51:05.000000 GET /test-req1
+ I 21569456 2008-09-12 15:51:05.000000 0
+ C 21569456 2008-09-12 15:51:05.000000
+ - 21569456 2008-09-12 15:51:05.000000 beep! beep!
+ A 21569456 2008-09-12 15:51:05.000000 200 ?
+ E 21569456 2008-09-12 15:51:05.000000
Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/tests.py
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/tests.py 2009-03-25 14:39:52 UTC (rev 98365)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/tests.py 2009-03-25 15:06:13 UTC (rev 98366)
@@ -24,8 +24,8 @@
checker = zope.testing.renormalizing.RENormalizing([
# normalize the channel id and iso8601 timestamp
- (re.compile(r'-?\d+ \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}'),
- '23418928 2008-08-26T10:55:00'),
+ (re.compile(r'-?\d+ \d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{6}'),
+ '23418928 2008-08-26 10:55:00.000000'),
])
Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py 2009-03-25 14:39:52 UTC (rev 98365)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py 2009-03-25 15:06:13 UTC (rev 98366)
@@ -28,15 +28,12 @@
tracelog = logging.getLogger('zc.tracelog')
-def _format_datetime(dt):
- return dt.replace(microsecond=0).isoformat()
-
def _log(channel_id, trace_code='-', msg=None, timestamp=None):
if timestamp is None:
timestamp = datetime.datetime.now()
- entry = '%s %s %s' % (trace_code, channel_id, _format_datetime(timestamp))
+ entry = '%s %s %s' % (trace_code, channel_id, timestamp)
if msg:
entry += ' %s' % repr(msg)[1:-1]
@@ -154,4 +151,4 @@
@zope.component.adapter(zope.app.appsetup.interfaces.IProcessStartingEvent)
def started(event):
- tracelog.info('S 0 %s', _format_datetime(datetime.datetime.now()))
+ tracelog.info('S 0 %s', datetime.datetime.now())
More information about the Checkins
mailing list