more tracelogging

1 files changed, 1 insertions, 0 deletions

diff --git a/backend/node/src/clipperz.js b/backend/node/src/clipperz.js
index b8b4d3e..04b054a 100644
--- a/backend/node/src/clipperz.js
+++ b/backend/node/src/clipperz.js
@@ -1,174 +1,175 @@
 var FS = require('fs');
 var CRYPTO = require('crypto');
 var BIGNUM = require('bignum');
 var ASYNC = require('async');
 
 var express_store = require('express').session.Store;
 
 function clipperz_hash(v) {
  return CRYPTO.createHash('sha256').update(
   CRYPTO.createHash('sha256').update(v).digest('binary')
  ).digest('hex');
 };
 function clipperz_random() {
  for(var r = '';r.length<64;r+=''+BIGNUM(Math.floor(Math.random()*1e18)).toString(16));
  return r.substr(0,64);
 };
 function clipperz_store(PG) {
  var rv = function(o) { express_store.call(this,o); }
  rv.prototype.get = function(sid,cb) { PG.Q(
   "SELECT s_data FROM clipperz.thesession WHERE s_id=$1",[sid],
   function(e,r) { cb(e,(e||!r.rowCount)?null:JSON.parse(r.rows[0].s_data)); }
  ) };
  rv.prototype.set = function(sid,data,cb) {
   var d = JSON.stringify(data);
   PG.Q(
     "UPDATE clipperz.thesession SET s_data=$1, s_mtime=current_timestamp"
    +" WHERE s_id=$2",[d,sid], function(e,r) {
    if(e) return cb(e);
    if(r.rowCount) return cb();
    PG.Q("INSERT INTO clipperz.thesession (s_id,s_data) VALUES ($1,$2)",[sid,d],cb);
   });
  };
  rv.prototype.destroy = function(sid,cb) { PG.Q(
   "DELETE FROM clipperz.thesession WHERE s_id=$1",[sid],cb
  ) };
  rv.prototype.length = function(cb) { PG.Q(
   "SELECT count(*) AS c FROM clipperz.thesession", function(e,r) {
      cb(e,e?null:r.rows[0].c);
   }
  ) };
  rv.prototype.length = function(cb) { PQ.Q(
   "DELETE FROM clipperz.thesession", cb
  ) };
  rv.prototype.__proto__ = express_store.prototype;
  return rv;
 }
 
 var srp_g = BIGNUM(2);
 var srp_n = BIGNUM("115b8b692e0e045692cf280b436735c77a5a9e8a9e7ed56c965f87db5b2a2ece3",16);
 var n123 = '112233445566778899aabbccddeeff00112233445566778899aabbccddeeff00';
 
 
 var CLIPPERZ = module.exports = function(CONFIG) {
 
  var LOGGER = CONFIG.logger||{trace:function(){}};
 
  var PG = {
   url: CONFIG.psql,
   PG: require('pg').native,
   Q: function(q,a,cb) {
    if('function'===typeof a) cb=a,a=[];
    LOGGER.trace({query:q,args:a},'SQL: %s',q);
    PG.PG.connect(PG.url,function(e,C,D) {
 	if(e) return cb(e);
 	var t0=new Date();
 	C.query(q,a,function(e,r) {
 	 var t1=new Date(), dt=t1-t0;
 	 D();
 	 LOGGER.trace({query:q,args:a,ms:dt,rows:r&&r.rowCount,err:e},"SQL query '%s' took %dms",q,dt);
 	 cb(e,r);
 	});
    });
   },
   T: function(cb) {
    PG.PG.connect(PG.url,function(e,C,D) {
 	if(e) return cb(e);
 	C.query('BEGIN',function(e){
 	 if(e) return D(),cb(e);
+	 LOGGER.trace('SQL: transaction begun');
 	 cb(null,{
 	  Q: function(q,a,cb) {
 	   LOGGER.trace({query:q,args:a},'SQL: %s',q);
 	   if(this.over) return cb(new Error('game over'));
 	   if('function'===typeof a) cb=a,a=[];
 	   var t0=new Date();
 	   C.query(q,a,function(e,r) {
 		var t1=new Date(), dt=t1-t0;
 		LOGGER.trace({query:q,args:a,ms:dt,rows:r&&r.rowCount,err:e},"SQL query '%s' took %dms",q,dt);
 		cb(e,r);
 	   });
 	  },
 	  commit: function(cb) {
 	   LOGGER.trace('SQL: commit');
 	   if(this.over) return cb(new Error('game over'));
 	   return (this.over=true),C.query('COMMIT',function(e){D();cb&&cb(e)});
 	  },
 	  rollback: function(cb) {
 	   LOGGER.trace('SQL: rollback');
 	   if(this.over) return cb(new Error('game over'));
 	   return (this.over=true),C.query('ROLLBACK',function(e){D();cb&&cb(e)});
 	  },
 	  end: function(e,cb) {
 	   if(e) return LOGGER.trace(e,"rolling back transaction due to an error"),this.rollback(cb);
 	   this.commit(cb);
 	  }
 	 });
 	});
    });
   }
  };
 
 
  var rv = {
 
   json: function clipperz_json(req,res,cb) {
    var method = req.body.method, pp = JSON.parse(req.body.parameters).parameters;
    var message = pp.message;
    var ppp = pp.parameters;
    res.res = function(o) { return res.json({result:o}) };
    LOGGER.trace({method:method,parameters:pp},"JSON request");
 
    switch(method) {
     case 'registration':
      switch(message) {
       case 'completeRegistration': return PG.Q(
 	"INSERT INTO clipperz.theuser"
        +" (u_name, u_srp_s,u_srp_v, u_authversion,u_header,u_statistics,u_version,u_lock)"
        +" VALUES ($1, $2,$3, $4,$5,$6,$7,$8)",
        [pp.credentials.C, pp.credentials.s, pp.credentials.v,
 	pp.credentials.version,pp.user.header, pp.user.statistics,
 	pp.user.version, pp.user.lock], function(e,r) {
 	if(e) return cb(e);
 	res.res({lock:pp.user.lock,result:'done'});
        });
      }
     break;
 
     case 'handshake':
      switch(message) {
       case 'connect': return ASYNC.auto({
        u: function(cb) { PG.Q(
 	"SELECT u_id, u_srp_s, u_srp_v FROM clipperz.theuser WHERE u_name=$1",
 	[ppp.C], function(e,r) {
 	if(e) return cb(e);
 	if(!r.rowCount) return cb(null,{u_id:null,u_srp_s:n123,u_srp_v:n123});
 	cb(null,r.rows[0]);
        }) },
        otp: ['u',function(cb,r) {
 	if(!req.session.otp) return cb();
 	if(req.session.u!=r.u.u_id) return cb(new Error('user/OTP mismatch'));
 	PG.Q(
 	  "UPDATE clipperz.theotp AS otp"
 	 +" SET"
 	 +"  otps_id=CASE WHEN s.otps_code='REQUESTED' THEN ("
 	 +"   SELECT ss.otps_id FROM clipperz.otpstatus AS ss WHERE ss.otps_code='USED'"
 	 +"  ) ELSE otp.otps_id END,"
 	 +"  otp_utime=current_timestamp"
 	 +" FROM clipperz.otpstatus AS s, clipperz.theotp AS o"
 	 +" WHERE"
 	 +"  o.otp_id=otp.otp_id AND otp.otps_id=s.otps_id"
 	 +"  AND otp.otp_id=$1 AND otp.u_id=$2"
 	 +" RETURNING o.otps_id!=otp.otps_id AS yes, o.otp_ref",
 	 [ req.session.otp, req.session.u ],
 	 function(e,r) {
 	 if(e) return cb(e);
 	 if(!r.rowCount) return cb(new Error('no OTP found'));
 	 r=r.rows[0];
 	 if(!r.yes) return cb(new Error('OTP is in a sorry state'));
 	 cb(null,{ref:r.otp_ref});
 	});
        }]
       },function(e,r) {
        if(e) return cb(e);
        req.session.C = ppp.C; req.session.A = ppp.A;
        req.session.s = r.u.u_srp_s; req.session.v = r.u.u_srp_v;