[Sks-devel] timestamping more precisely, merging logs

[Jason Harris]

For various reasons, I patched SKS to timestamp events more precisely.
To get output that includes microseconds:

  [db.log]
  2005-07-18 18:58:53 0.053317 Applying 2 changes
  2005-07-18 18:58:53 0.053352 Adding hash 0B2728A61F285C2273B542BC4014D679
  2005-07-18 18:58:53 0.053378 Del'ng hash 1F46050134AA477D17245DB63E044EBA
  2005-07-18 18:58:53 0.444974 Sending LogResp size 2

  [recon.log]
  2005-07-18 18:58:52 0.822811 1 keys received
  2005-07-18 18:58:53 0.655559 setting synctime to 1121713133.049091
  2005-07-18 18:58:53 0.655967 Added 2 hash-updates. Caught up to 
1121713133.049091

and allows the db.log and recon.log entries to be intelligibly merged
together using sort(1):

  [recon event]
  2005-07-18 18:58:52 0.822811 1 keys received
  [db events, in their original order]
  2005-07-18 18:58:53 0.053317 Applying 2 changes
  2005-07-18 18:58:53 0.053352 Adding hash 0B2728A61F285C2273B542BC4014D679
  2005-07-18 18:58:53 0.053378 Del'ng hash 1F46050134AA477D17245DB63E044EBA
  2005-07-18 18:58:53 0.444974 Sending LogResp size 2
  [correctly followed by recon events, also in their original order]
  2005-07-18 18:58:53 0.655559 setting synctime to 1121713133.049091
  2005-07-18 18:58:53 0.655967 Added 2 hash-updates. Caught up to 1121713133.049
091

apply this patch:

--- orig/common.ml
+++ mod/common.ml
@@ -66,11 +66,13 @@
   kprintf (fun s -> 
             if !Settings.debug && level  <= !Settings.debuglevel 
             then  (
-              let tm = Unix.localtime (Unix.time ()) in
-              fprintf !logfile "%04d-%02d-%02d %02d:%02d:%02d " 
+               let now = Unix.gettimeofday() in
+              let tm = Unix.localtime (now) in
+              let us = now -. floor now in
+              fprintf !logfile "%04d-%02d-%02d %02d:%02d:%02d %0.6f " 
                 (tm.Unix.tm_year + 1900) (tm.Unix.tm_mon + 1) 
                 tm.Unix.tm_mday (* date *)
-                tm.Unix.tm_hour tm.Unix.tm_min tm.Unix.tm_sec; (* time *)
+                tm.Unix.tm_hour tm.Unix.tm_min tm.Unix.tm_sec us; (* time *)
               output_string !logfile s; 
               output_string !logfile "\n";
               flush !logfile;
@@ -103,11 +105,13 @@
   kprintf (fun s ->
             if !Settings.debug && level  <= !Settings.debuglevel 
             then  (
-              let tm = Unix.localtime (Unix.time ()) in
-              fprintf !logfile "%04d-%02d-%02d %02d:%02d:%02d " 
+               let now = Unix.gettimeofday() in
+              let tm = Unix.localtime (now) in
+              let us = now -. floor now in
+              fprintf !logfile "%04d-%02d-%02d %02d:%02d:%02d %0.6f " 
                 (tm.Unix.tm_year + 1900) (tm.Unix.tm_mon + 1) 
                 tm.Unix.tm_mday (* date *)
-                tm.Unix.tm_hour tm.Unix.tm_min tm.Unix.tm_sec;
+                tm.Unix.tm_hour tm.Unix.tm_min tm.Unix.tm_sec us;
               output_string !logfile s;
               fprintf !logfile ": %s\n" (err_to_string e);
               flush !logfile;
--- orig/wserver.ml
+++ mod/wserver.ml
@@ -211,7 +211,7 @@
   let pieces = List.map ~f:(fun (x,y) -> sprintf "%s:%s" x y) 
                 (Map.to_alist map)
   in
-  "\n" ^ (String.concat "\n" pieces)
+  "+" ^ (String.concat "+" pieces)
 
 let request_to_string request = 
   let (kind,req,headers) = 

-- 
Jason Harris           |  NIC:  JH329, PGP:  This _is_ PGP-signed, isn't it?
address@hidden _|_ web:  http://keyserver.kjsl.com/~jharris/
          Got photons?   (TM), (C) 2004

pgpklMR2zHnF6.pgp
Description: PGP signature