add lots of logging looking for a problem

tes/apiendpoints.py

@@ -25,29 +25,31 @@ class GetCert(Resource):
         """
         takes a public key, returns to the SPA a certificate
         """
-        print("in GetCert.post")
+        import logging
+        logger = logging.getLogger()
+        logger.debug('entering GetCert.post')
         data = request.get_json()
-        print(data)
-        return {'cert':GetCert.get_cert(data['token'], data['pubkey'], data['signing_url'])}
-
+        try:
+            response = {'cert':GetCert.get_cert(data['token'], data['pubkey'], data['signing_url'])}
+        except:
+            import traceback
+            logger.error('Failed to get certificate')
+            logger.error(traceback.format_exc())
+            response = ("Unable to get a signed certificate",500)
+        return response
     @staticmethod
     def get_cert(access_token, pub_key, url):
         """
         Sign a pub key into a cert
         """
         import requests
-        print("accss_token {}".format(access_token))
-        print("pub_key {}".format(pub_key))
-        print("url {}".format(url))
+        import logging
+        logger = logging.getLogger()
         sess = requests.Session()
         headers = {"Authorization":"Bearer %s"%access_token}
         data = {"public_key":pub_key}
         resp = sess.post(url, json=data, headers=headers, verify=False)
-        print("get_cert returned from its external call")
         data = resp.json()
-        import logging
-        logger = logging.getLogger()
-        logger.debug('attempted get_cert {}'.format(data))
         return data['certificate']
 
 class TestAuth(Resource):
@@ -63,16 +65,16 @@ class TestAuth(Resource):
 
 class SSHAgent(Resource):
     def post(self):
+        import logging
+        logger = logging.getLogger()
+        logger.debug('entering SSHAgent.post')
         session.permanent = True
         from .tunnelstat import SSHSession
         sshsess = SSHSession.get_sshsession()
         data = request.get_json()
-        import logging
-        logger = logging.getLogger()
-        logger.debug('adding a key to the session')
         sshsess.add_keycert(key=data['key'],cert=data['cert'])
-        logger.debug('started an agent and added the key')
         sshsess.refresh()
+        logger.debug('leaving SSHAgent.post')
         return "OK"
 
     def get(self):
@@ -103,6 +105,9 @@ def get_conn_params():
     Return parameters relating to the backend compute service
     Retrieve them from the query string
     """
+    import logging
+    logger = logging.getLogger()
+    logger.debug('entering get_conn_params')
     identitystr = request.args.get('identity')
     identityparams = json.loads(identitystr)
     interfacestr = request.args.get('interface')
@@ -111,6 +116,9 @@ def get_conn_params():
         appstr = request.args.get('app')
         appparams = json.loads(appstr)
     except:
+        import traceback
+        logger.error('exception retrieving app params')
+        logger.error(traceback.format_exc())
         appparams = {}
     params = {}
 
@@ -122,6 +130,8 @@ def get_conn_params():
     params['user'] = identityparams['username']
     params['host'] = identityparams['site']['host']
 
+    logger.debug('leaving get_conn_params')
+
     return params
 
 
@@ -150,15 +160,27 @@ class TunnelstatEP(Resource):
         """
         import logging
         logger = logging.getLogger()
+        logger.debug('entering TunnelstatEP.get')
         from . import sshsessions
         from flask import session
+        logger.debug('TunnelstatEP.get: iterating sshsessions {}'.format(authtok))
+        port = None
 
-        for (id,sshsess) in sshsessions.items():
-            for (tok,port) in sshsess.port.items():
-                if tok == authtok:
-                    print("found port {} for authtok {}".format(port,tok))
-                    logger.debug("found port {} for authtok {}".format(port,tok))
-                    return port
+        try:
+            for (sessid,sshsess) in sshsessions.items():
+                logger.debug('sshsession id {}'.format(sessid))
+                for (tok,port) in sshsess.port.items():
+                    logger.debug('token {}'.format(tok))
+                    if tok == authtok:
+                        logger.debug("found port {} for authtok {}".format(port,tok))
+                        logger.debug('leaving TunnelstatEP.get')
+                        return port
+        except:
+            logger.error("exception in TunnelstatEP.get")
+            import traceback
+            logger.error(traceback.format_exc())
+        logger.debug("No ports found for authtok {} {}".format(port,authtok))
+        logger.debug('leaving TunnelstatEP.get')
         return None
 
 class JobStat(Resource):
@@ -171,11 +193,9 @@ class JobStat(Resource):
         """
         import logging
         logger = logging.getLogger()
-        logger.info('/stat endpoint entered')
         params = get_conn_params()
         sshsess = SSHSession.get_sshsession()
         sshsess.refresh()
-        logger.info('/stat endpoint, all parameters collected')
         try:
             host = params['identity']['site']['host']
         except (TypeError, KeyError) as e:
@@ -230,15 +250,14 @@ class JobSubmit(Resource):
         import logging
         logger=logging.getLogger()
         params = get_conn_params()
-        logger.debug('submitting with parameters {}'.format(params))
+        logger.debug('entering JobSubmit.post {}'.format(params))
         sshsess = SSHSession.get_sshsession()
         res = Ssh.execute(sshsess, host=params['identity']['site']['host'], user=params['identity']['username'],
                           cmd=params['interface']['submitcmd'], stdin=params['app']['startscript'])
         if not (res['stderr'] == '' or res['stderr'] is None or res['stderr'] == b''):
-            print(res['stderr'])
+            logger.debug('failed to submit job')
             logger.debug(res['stderr'])
             flask_restful.abort(400, message=res['stderr'].decode())
-        logger.debug(res['stdout'])
         return res['stdout'].decode()
 
 def gen_authtok():
@@ -247,6 +266,9 @@ def gen_authtok():
     """
     import random
     import string
+    import logging
+    logger=logging.getLogger()
+    logger.debug('generating new authtok')
     return ''.join(random.SystemRandom().choice(string.ascii_uppercase +
                                                 string.digits) for _ in range(16))
 
@@ -256,12 +278,16 @@ class JobConnect(Resource):
     """
 
     def create_tunnel(self, username, loginhost, appparams, batchhost, firewall, data):
+        import logging
+        logger=logging.getLogger()
+        logger.debug('entering JobConnect.create_tunnel {} {}'.format(username,batchhost))
         connectparams = {}
         sshsess = SSHSession.get_sshsession()
 
         if 'paramscmd' in appparams and appparams['paramscmd'] is not None:
             connectparams['batchhost'] = batchhost
-            paramcmd = 'ssh -o StrictHostKeyChecking=no {batchhost} '.format(batchhost=batchhost) + appparams['paramscmd']
+            paramcmd = 'ssh -o StrictHostKeyChecking=no -o CheckHostIP=no {batchhost} '.format(batchhost=batchhost) + appparams['paramscmd']
+            logger.debug('JobCreate.create_tunnel: using ssh to extract connection parameters')
             res = Ssh.execute(sshsess, host=loginhost, user=username, cmd=paramcmd.format(data))
             try:
                 data = json.loads(res['stdout'])
@@ -274,13 +300,14 @@ class JobConnect(Resource):
             try:
                 connectparams.update(json.loads(res['stdout']))
             except json.decoder.JSONDecodeError as e:
-                print(res['stdout'])
-                print(res['stderr'])
+                logger.error(res['stdout'])
+                logger.error(res['stderr'])
             if not (res['stderr'] == '' or res['stderr'] is None or res['stderr'] == b''):
                 flask_restful.abort(400, message=res['stderr'].decode())
 
             if self.validate_connect_params(connectparams, username, loginhost):
                 authtok = gen_authtok()
+                logger.debug('JobCreate.create_tunnel: creating a tunnel for authtok {}'.format(authtok))
                 tunnelport, pids = Ssh.tunnel(sshsess, port=connectparams['port'],
                                               batchhost=connectparams['batchhost'],
                                               user=username, host=loginhost,
@@ -289,6 +316,7 @@ class JobConnect(Resource):
 
                 connectparams['localtunnelport'] = tunnelport
                 connectparams['authtok'] = authtok
+                logger.debug('JobCreate.create_tunnel: created a tunnel for authtok {} port {}'.format(authtok,tunnelport))
             else:
                 raise AppParamsException("connection parameters invalid {} {} {}".format(connectparams,username,loginhost))
         return connectparams
@@ -312,8 +340,10 @@ class JobConnect(Resource):
         """
         Connecting to a job is a get operation (i.e. it does not make modifications)
         """
+        import logging
+        logger=logging.getLogger()
+        logger.debug('entering JobConnect.get for jobid {} {}'.format(jobid,batchhost))
         params = get_conn_params()
-        print(params['interface'])
         appparams = get_app_params()
         data = request.get_json()
         try:
@@ -322,6 +352,7 @@ class JobConnect(Resource):
                                             data)
         except AppParamsException as e:
             return make_response(render_template('appparams.html.j2',data = "{}".format(e)))
+        logger.debug('JobConnect.get tunnels created, moving to redirect'.format(jobid,batchhost))
         return self.connect(appparams, connectparams)
 
     def connect(self, appparams, connectparams):
@@ -329,6 +360,8 @@ class JobConnect(Resource):
         perform the connection either by forking a local client or returning a redirect
         """
         import subprocess
+        import logging
+        logger=logging.getLogger()
         if 'cmd' in appparams['client'] and appparams['client']['cmd'] is not None:
             # We need for fork a local process such as vncviewer or a terminal
             # We may need a wrapper for local processes to find the correct
@@ -337,9 +370,6 @@ class JobConnect(Resource):
             for cmdarg in appparams['client']['cmd']:
                 cmdlist.append(cmdarg.format(**connectparams))
             app_process = subprocess.Popen(cmdlist, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
-#            stdout, stderr = app_process.communicate()
-#            if stderr is not "":
-#                return "connected with cmd {} but got error {}".format(cmdlist,stderr)
         elif 'redir' in appparams['client'] and appparams['client']['redir'] is not None:
             template_response = Response()
             template_response.set_cookie(key='twsproxyauth', value=connectparams['authtok'])
@@ -347,6 +377,7 @@ class JobConnect(Resource):
             response = make_response(redirect(twsproxy+appparams['client']['redir'].
                                               format(**connectparams)))
             response.set_cookie('twsproxyauth', connectparams['authtok'])
+            logger.debug('JobConnect.connect: connecting via redirect with cookie authtok set to  {}'.format(connectparams['authtok']))
             return response
         return "Connecting with cmd {}".format(cmdlist)