Add config knob for cgitb traceback logs

Adds "trace_file" a configuration knob to python daemons
that defaults to previouly hardcoded value

Exceptions while accessing this log file are now cathed
in vnc_openstack, in order to avoid side effects that are
described in attached bug.

Api_server extension loading is also changed to provide
sandesh logger to vnc_openstack. vnc_openstack exceptions
messages will be logged with api-server logs (for now,
they were only printed to local trace_file and/or stdout).

Partial-Bug: #1335062

Change-Id: Id2d28e5e2ef65c93c87b080b53e838ce65c0416d

src/config/api-server/vnc_cfg_api_server.py

@@ -734,6 +734,7 @@ def _parse_args(self, args_str):
                                          --logging_conf <logger-conf-file>
                                          --log_category test
                                          --log_file <stdout>
+                                         --trace_file /var/log/contrail/vnc_openstack.err
                                          --use_syslog
                                          --syslog_facility LOG_USER
                                          --disc_server_ip 127.0.0.1
@@ -769,6 +770,7 @@ def _parse_args(self, args_str):
             'log_level': SandeshLevel.SYS_NOTICE,
             'log_category': '',
             'log_file': Sandesh._DEFAULT_LOG_FILE,
+            'trace_file': '/var/log/contrail/vnc_openstack.err',
             'use_syslog': False,
             'syslog_facility': Sandesh._DEFAULT_SYSLOG_FACILITY,
             'logging_level': 'WARN',
@@ -914,6 +916,9 @@ def _parse_args(self, args_str):
         parser.add_argument(
             "--log_file",
             help="Filename for the logs to be written to")
+        parser.add_argument(
+            "--trace_file", default='/var/log/contrail/vnc_openstack.err',
+            help="Filename for the errors backtraces to be written to")
         parser.add_argument("--use_syslog",
             action="store_true",
             help="Use syslog for logging")
@@ -975,17 +980,17 @@ def _load_extensions(self):
             self._extension_mgrs['resync'] = ExtensionManager(
                 'vnc_cfg_api.resync', api_server_ip=self._args.listen_ip_addr,
                 api_server_port=self._args.listen_port,
-                conf_sections=conf_sections)
+                conf_sections=conf_sections, sandesh=self._sandesh)
             self._extension_mgrs['resourceApi'] = ExtensionManager(
                 'vnc_cfg_api.resourceApi',
                 api_server_ip=self._args.listen_ip_addr,
                 api_server_port=self._args.listen_port,
-                conf_sections=conf_sections)
+                conf_sections=conf_sections, sandesh=self._sandesh)
             self._extension_mgrs['neutronApi'] = ExtensionManager(
                 'vnc_cfg_api.neutronApi',
                 api_server_ip=self._args.listen_ip_addr,
                 api_server_port=self._args.listen_port,
-                conf_sections=conf_sections)
+                conf_sections=conf_sections, sandesh=self._sandesh)
         except Exception as e:
             self.config_log("Exception in extension load: %s" %(str(e)),
                 level=SandeshLevel.SYS_ERR)

src/config/common/vnc_extensions.py

@@ -51,12 +51,13 @@ def inner(*args, **kwargs):
 
 class ExtensionManager(stevedore.extension.ExtensionManager):
     def __init__(self, namespace, api_server_ip,
-                 api_server_port, conf_sections):
+                 api_server_port, conf_sections, sandesh):
         super(ExtensionManager, self).__init__(
             namespace, invoke_on_load=True,
             invoke_kwds={'api_server_ip': api_server_ip,
                          'api_server_port': api_server_port,
-                         'conf_sections': conf_sections, })
+                         'conf_sections': conf_sections,
+                         'sandesh': sandesh })
     #end __init__
 
 #end class ExtensionManager

src/config/schema-transformer/to_bgp.py

@@ -3679,11 +3679,12 @@ def launch_arc(transformer, ssrc_mapc):
                     format="text",
                     ).handle(sys.exc_info())
                 try:
-                    with open('/var/log/contrail/schema.err', 'a') as err_file:
+                    with open(transformer._args.trace_file, 'a') as err_file:
                         err_file.write(string_buf.getvalue())
                 except IOError:
-                    with open('./schema.err', 'a') as err_file:
-                        err_file.write(string_buf.getvalue())
+                    transformer._sandesh._logger.debug(
+                        "Failed to open trace file %s: %s" %
+                        (transformer._args.trace_file, IOError))
                 if type(e) == InvalidSessionID:
                     return
                 raise e
@@ -3717,6 +3718,7 @@ def parse_args(args_str):
                          --log_level SYS_DEBUG
                          --log_category test
                          --log_file <stdout>
+                         --trace_file /var/log/contrail/schema.err
                          --use_syslog
                          --syslog_facility LOG_USER
                          --cluster_id <testbed-name>
@@ -3749,6 +3751,7 @@ def parse_args(args_str):
         'log_level': SandeshLevel.SYS_DEBUG,
         'log_category': '',
         'log_file': Sandesh._DEFAULT_LOG_FILE,
+        'trace_file': '/var/log/contrail/schema.err',
         'use_syslog': False,
         'syslog_facility': Sandesh._DEFAULT_SYSLOG_FACILITY,
         'cluster_id': '',
@@ -3832,6 +3835,8 @@ def parse_args(args_str):
         help="Category filter for local logging of sandesh messages")
     parser.add_argument("--log_file",
                         help="Filename for the logs to be written to")
+    parser.add_argument("--trace_file", help="Filename for the error "
+                        "backtraces to be written to")
     parser.add_argument("--use_syslog", action="store_true",
                         help="Use syslog for logging")
     parser.add_argument("--syslog_facility",

src/config/svc-monitor/svc_monitor/svc_monitor.py

@@ -15,6 +15,7 @@
 import requests
 import ConfigParser
 import cgitb
+from cStringIO import StringIO
 import argparse
 import socket
 
@@ -70,22 +71,16 @@ def __init__(self, args=None):
         self.db.init_database()
 
         # rotating log file for catchall errors
-        self._err_file = '/var/log/contrail/svc-monitor.err'
-        self._tmp_file = '/var/log/contrail/svc-monitor.tmp'
+        self._err_file = self._args.trace_file
+        self._svc_err_logger = logging.getLogger('SvcErrLogger')
+        self._svc_err_logger.setLevel(logging.ERROR)
         try:
             with open(self._err_file, 'a'):
-                pass
-            with open(self._tmp_file, 'a'):
-                pass
+                handler = logging.handlers.RotatingFileHandler(
+                    self._err_file, maxBytes=64*1024, backupCount=2)
+                self._svc_err_logger.addHandler(handler)
         except IOError:
-            self._err_file = './svc-monitor.err'
-            self._tmp_file = './svc-monitor.tmp'
-        self._svc_err_logger = logging.getLogger('SvcErrLogger')
-        self._svc_err_logger.setLevel(logging.ERROR)
-        handler = logging.handlers.RotatingFileHandler(
-            self._err_file, maxBytes=64*1024, backupCount=2)
-        self._svc_err_logger.addHandler(handler)
-
+            self.logger.log("Failed to open trace file %s" % self._err_file)
 
     def post_init(self, vnc_lib, args=None):
         # api server
@@ -544,10 +539,10 @@ def launch_timer(monitor):
             cgitb_error_log(monitor)
 
 def cgitb_error_log(monitor):
-    cgitb.Hook(format="text",
-               file=open(monitor._tmp_file, 'w')).handle(sys.exc_info())
-    fhandle = open(monitor._tmp_file)
-    monitor._svc_err_logger.error("%s" % fhandle.read())
+    tmp_file = StringIO()
+    cgitb.Hook(format="text", file=tmp_file).handle(sys.exc_info())
+    monitor._svc_err_logger.error("%s" % tmp_file.getvalue())
+    tmp_file.close()
 
 def parse_args(args_str):
     '''
@@ -568,6 +563,7 @@ def parse_args(args_str):
                          --log_level SYS_DEBUG
                          --log_category test
                          --log_file <stdout>
+                         --trace_file /var/log/contrail/svc-monitor.err
                          --use_syslog
                          --syslog_facility LOG_USER
                          --cluster_id <testbed-name>
@@ -601,6 +597,7 @@ def parse_args(args_str):
         'log_level': SandeshLevel.SYS_DEBUG,
         'log_category': '',
         'log_file': Sandesh._DEFAULT_LOG_FILE,
+        'trace_file': '/var/log/contrail/svc-monitor.err',
         'use_syslog': False,
         'syslog_facility': Sandesh._DEFAULT_SYSLOG_FACILITY,
         'region_name': None,
@@ -698,6 +695,8 @@ def parse_args(args_str):
         help="Category filter for local logging of sandesh messages")
     parser.add_argument("--log_file",
                         help="Filename for the logs to be written to")
+    parser.add_argument("--trace_file", help="Filename for the error "
+                        "backtraces to be written to")
     parser.add_argument("--use_syslog", action="store_true",
                         help="Use syslog for logging")
     parser.add_argument("--syslog_facility",

src/config/vnc_openstack/vnc_openstack/__init__.py

@@ -9,6 +9,7 @@
 import requests
 import cgitb
 import copy
+from cStringIO import StringIO
 import bottle
 import logging
 import logging.handlers
@@ -21,9 +22,9 @@
     from cfgm_common import vnc_plugin_base
 except ImportError:
     from common import vnc_plugin_base
+from pysandesh.sandesh_base import *
+from pysandesh.sandesh_logger import *
 from vnc_api import vnc_api
-from vnc_api.gen.resource_xsd import *
-
 from vnc_api.gen.resource_xsd import *
 from vnc_api.gen.resource_common import *
 
@@ -59,11 +60,15 @@ def fill_keystone_opts(obj, conf_sections):
         obj._auth_port = conf_sections.get('KEYSTONE', 'auth_port')
         obj._auth_url = "%s://%s:%s/v2.0" % (obj._auth_proto, obj._auth_host,
                                              obj._auth_port)
+    try:
+        obj._err_file = conf_sections.get('DEFAULTS', 'trace_file')
+    except ConfigParser.NoOptionError:
+        obj._err_file = '/var/log/contrail/vnc_openstack.err'
 
 
 openstack_driver = None
 class OpenstackDriver(vnc_plugin_base.Resync):
-    def __init__(self, api_server_ip, api_server_port, conf_sections):
+    def __init__(self, api_server_ip, api_server_port, conf_sections, sandesh):
         global openstack_driver
         openstack_driver = self
         if api_server_ip == '0.0.0.0':
@@ -110,26 +115,27 @@ def __init__(self, api_server_ip, api_server_port, conf_sections):
         self._vnc_project_ids = set()
 
         # logging
-        self._log_file_name = '/var/log/contrail/vnc_openstack.err'
-        self._tmp_file_name = '/var/log/contrail/vnc_openstack.tmp'
+        self._sandesh_logger = sandesh.logger()
         self._vnc_os_logger = logging.getLogger(__name__)
         self._vnc_os_logger.setLevel(logging.ERROR)
         # Add the log message handler to the logger
         try:
-            handler = logging.handlers.RotatingFileHandler(self._log_file_name,
-                                                           maxBytes=1024,
-                                                           backupCount=5)
+            with open(self._err_file, 'a'):
+                handler = logging.handlers.RotatingFileHandler(
+                    self._err_file, maxBytes=64*1024, backupCount=5)
+                self._vnc_os_logger.addHandler(handler)
         except IOError:
-            self._log_file_name = './vnc_openstack.err'
-            self._tmp_file_name = './vnc_openstack.tmp'
-            handler = logging.handlers.RotatingFileHandler(self._log_file_name,
-                                                           maxBytes=1024,
-                                                           backupCount=5)
-
-        self._vnc_os_logger.addHandler(handler)
+            self._sandesh_logger.error("Failed to open trace file %s" %
+                                       self._err_file)
         self.q = Queue.Queue(maxsize=Q_MAX_ITEMS)
     #end __init__
 
+    def _cgitb_error_log(self):
+        tmp_file = StringIO()
+        cgitb.Hook(format="text", file=tmp_file).handle(sys.exc_info())
+        self._vnc_os_logger.error("%s" % tmp_file.getvalue())
+        tmp_file.close()
+
     def __call__(self):
         pass
     #end __call__
@@ -206,12 +212,9 @@ def _ksv2_del_project_from_vnc(self, project_id):
         except vnc_api.NoIdError:
             pass
         except Exception as e:
-            cgitb.Hook(
-                format="text",
-                file=open(self._tmp_file_name,
-                          'w')).handle(sys.exc_info())
-            fhandle = open(self._tmp_file_name)
-            self._vnc_os_logger.error("%s" % fhandle.read())
+            self._cgitb_error_log()
+            self._sandesh_logger.error("Failed to delete project %s: %s" %
+                                       (project_id, e))
             self._failed_project_dels.add(project_id)
     # _ksv2_del_project_from_vnc
 
@@ -321,12 +324,9 @@ def _ksv3_del_project_from_vnc(self, project_id):
         except vnc_api.NoIdError:
             pass
         except Exception as e:
-            cgitb.Hook(
-                format="text",
-                file=open(self._tmp_file_name,
-                          'w')).handle(sys.exc_info())
-            fhandle = open(self._tmp_file_name)
-            self._vnc_os_logger.error("%s" % fhandle.read())
+            self._cgitb_error_log()
+            self._sandesh_logger.error("Failed to delete project %s "
+                                       "from vnc: %s" % (project_id, e))
             self._failed_project_dels.add(project_id)
     # _ksv3_del_project_from_vnc
 
@@ -369,12 +369,9 @@ def _del_domain_from_vnc(self, domain_id):
         except vnc_api.NoIdError:
             pass
         except Exception as e:
-            cgitb.Hook(
-                format="text",
-                file=open(self._tmp_file_name,
-                          'w')).handle(sys.exc_info())
-            fhandle = open(self._tmp_file_name)
-            self._vnc_os_logger.error("%s" % fhandle.read())
+            self._sandesh_logger.error("Failed to delete domain %s "
+                                       "from vnc: %s" % (domain_id, e))
+            self._cgitb_error_log()
             self._failed_domain_dels.add(domain_id)
     # _del_domain_from_vnc
 
@@ -482,12 +479,9 @@ def _resync_domains_projects_forever(self):
                                  if proj['fq_name'] != default_proj_fq_name])
             self._vnc_project_ids = vnc_project_ids
         except Exception as e:
-            cgitb.Hook(
-                format="text",
-                file=open(self._tmp_file_name,
-                          'w')).handle(sys.exc_info())
-            fhandle = open(self._tmp_file_name)
-            self._vnc_os_logger.error("%s" % fhandle.read())
+            self._cgitb_error_log()
+            self._sandesh_logger.error(
+                "Connection to API server failed: %s" %  e)
 
         while True:
             # Get domains/projects from Keystone and audit with api-server
@@ -497,27 +491,19 @@ def _resync_domains_projects_forever(self):
                     continue
             except Exception as e:
                 self._ks = None
-                cgitb.Hook(
-                    format="text",
-                    file=open(self._tmp_file_name,
-                              'w')).handle(sys.exc_info())
-                fhandle = open(self._tmp_file_name)
-                self._vnc_os_logger.error("%s" % fhandle.read())
-                gevent.sleep(2)
+                self._cgitb_error_log()
+                self._sandesh_logger.error(
+                    "Failed to resync domains: %s" %  e)
 
             try:
                 retry = self._resync_all_projects()
                 if retry:
                     continue
             except Exception as e:
                 self._ks = None
-                cgitb.Hook(
-                    format="text",
-                    file=open(self._tmp_file_name,
-                              'w')).handle(sys.exc_info())
-                fhandle = open(self._tmp_file_name)
-                self._vnc_os_logger.error("%s" % fhandle.read())
-                gevent.sleep(2)
+                self._cgitb_error_log()
+                self._sandesh_logger.error(
+                    "Failed to resync projects: %s" %  e)
 
             gevent.sleep(self._resync_interval_secs)
 
@@ -566,7 +552,7 @@ def _resync_worker(self):
 
 
 class ResourceApiDriver(vnc_plugin_base.ResourceApi):
-    def __init__(self, api_server_ip, api_server_port, conf_sections):
+    def __init__(self, api_server_ip, api_server_port, conf_sections, sandesh):
         if api_server_ip == '0.0.0.0':
             self._vnc_api_ip = '127.0.0.1'
         else:
@@ -698,9 +684,9 @@ def pre_virtual_network_create(self, vn_dict):
 # end class ResourceApiDriver
 
 class NeutronApiDriver(vnc_plugin_base.NeutronApi):
-    def __init__(self, api_server_ip, api_server_port, conf_sections):
+    def __init__(self, api_server_ip, api_server_port, conf_sections, sandesh):
         self._npi = npi.NeutronPluginInterface(api_server_ip, api_server_port,
-                                               conf_sections)
+                                               conf_sections, sandesh)
 
         # Bottle callbacks for network operations
         bottle.route('/neutron/network',