[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