Change in python/osmo-python-tests[master]: ctrl2cgi: log request time

[Harald Welte]

Harald Welte has submitted this change and it was merged. ( https://gerrit.osmocom.org/12147 )

Change subject: ctrl2cgi: log request time
......................................................................

ctrl2cgi: log request time

Log http request timestamp and duration on debug loglevel. This is
especially helpful while troubleshooting issues with multiple concurrent
requests under significant load while network issues are present.

Change-Id: I11c8ac67a2730a9c6912694e5b83bbdf08fe357d
Related: SYS#4399
---
M scripts/ctrl2cgi.py
1 file changed, 9 insertions(+), 6 deletions(-)

Approvals:
  Jenkins Builder: Verified
  Harald Welte: Looks good to me, approved

Objections:
  daniel: I would prefer this is not merged as is



diff --git a/scripts/ctrl2cgi.py b/scripts/ctrl2cgi.py
index 5c675bc..e11e6e6 100755
--- a/scripts/ctrl2cgi.py
+++ b/scripts/ctrl2cgi.py
@@ -22,9 +22,9 @@
  */
 """
 
-__version__ = "0.0.6" # bump this on every non-trivial change
+__version__ = "0.0.7" # bump this on every non-trivial change
 
-import argparse, os, logging, logging.handlers
+import argparse, os, logging, logging.handlers, datetime
 import hashlib
 import json
 import configparser
@@ -40,11 +40,12 @@
 assert V(twisted_ipa_version) > V('0.4')
 
 
-def handle_reply(bid, f, log, resp):
+def handle_reply(ts, bid, f, log, resp):
     """
     Reply handler: process raw CGI server response, function f to run for each command
     """
     decoded = json.loads(resp.decode('utf-8'))
+    log.debug('request for BSC %s took %d seconds' % (bid, (datetime.datetime.now() - ts).total_seconds()))
     comm_proc(decoded.get('commands'), bid, f, log)
 
 def gen_hash(params, skey):
@@ -60,9 +61,9 @@
     #print('HASH: \nparams="%r"\ninput="%s" \nres="%s"' %(params, input, res))
     return res
 
-def make_async_req(dst, par, f_write, f_log):
+def make_async_req(ts, dst, par, f_write, f_log):
     d = post(dst, par)
-    d.addCallback(collect, partial(handle_reply, par['bsc_id'], f_write, f_log)) # treq's collect helper is handy to get all reply content at once
+    d.addCallback(collect, partial(handle_reply, ts, par['bsc_id'], f_write, f_log)) # treq's collect helper is handy to get all reply content at once
     d.addErrback(lambda e: f_log.critical("HTTP POST error %s while trying to register BSC %s on %s" % (e, par['bsc_id'], dst))) # handle HTTP errors
     return d
 
@@ -106,8 +107,10 @@
         params = make_params(bsc, data)
         self.factory.log.info('location-state@%s.%s.%s.%s (%s) => %s' % (net, bsc, bts, trx, params['time_stamp'], data))
         params['h'] = gen_hash(params, self.factory.secret_key)
+        t = datetime.datetime.now()
+        self.factory.log.debug('Preparing request for BSC %s @ %s...' % (params['bsc_id'], t))
         # Ensure that we run only limited number of requests in parallel:
-        self.factory.semaphore.run(make_async_req, self.factory.location, params, self.transport.write, self.factory.log)
+        self.factory.semaphore.run(make_async_req, t, self.factory.location, params, self.transport.write, self.factory.log)
 
     def handle_notificationrejectionv1(self, net, bsc, bts, trx, data):
         """

-- 
To view, visit https://gerrit.osmocom.org/12147
To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings

Gerrit-Project: python/osmo-python-tests
Gerrit-Branch: master
Gerrit-MessageType: merged
Gerrit-Change-Id: I11c8ac67a2730a9c6912694e5b83bbdf08fe357d
Gerrit-Change-Number: 12147
Gerrit-PatchSet: 1
Gerrit-Owner: Max <msuraev at sysmocom.de>
Gerrit-Reviewer: Harald Welte <laforge at gnumonks.org>
Gerrit-Reviewer: Jenkins Builder (1000002)
Gerrit-Reviewer: Pau Espin Pedrol <pespin at sysmocom.de>
Gerrit-Reviewer: daniel <dwillmann at sysmocom.de>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.osmocom.org/pipermail/gerrit-log/attachments/20181206/7a2f93ec/attachment.htm>