suds-jurko instrumentation (#75)

* Add background Soap server to test suite.

* Better exception capture & logging in metric thread

* Initial suds-jurko instrumentation

* Basic Soap request tests.

* Add SoapData section; Add soap as registered span

* Cleanup and organize package dependencies

* New test dependencies for Travis

* Version sensitive class & method

* Add requests to test bundle

* Remove unicode characters; silence spyne logging

* Exception & fault logging plus tests

* Move exception logging out to span

* Python 2 <-> 3 compatibility change

* Moar HTTP tags.

* Remove debug remnant and fix logger call

Author: pglombardo

.travis.yml

@@ -5,5 +5,5 @@ python:
   - "3.4"
   - "3.5"
   - "3.6"
-install: "pip install -r test_requirements.txt"
+install: "pip install -r requirements-test.txt"
 script: nosetests -v

instana/__init__.py

@@ -9,6 +9,7 @@
     # Import & initialize instrumentation
     # noqa: ignore=W0611
     from .instrumentation import urllib3  # noqa
+    from .instrumentation import sudsjurko  # noqa
 
 """
 The Instana package has two core components: the sensor and the tracer.

instana/instrumentation/sudsjurko.py

@@ -0,0 +1,48 @@
+from __future__ import absolute_import
+import instana
+from instana.log import logger
+import opentracing
+import opentracing.ext.tags as ext
+import wrapt
+
+
+try:
+    import suds # noqa
+
+    if (suds.version.__version__ <= '0.6'):
+        class_method = 'SoapClient.send'
+    else:
+        class_method = '_SoapClient.send'
+
+    @wrapt.patch_function_wrapper('suds.client', class_method)
+    def send_with_instana(wrapped, instance, args, kwargs):
+        context = instana.internal_tracer.current_context()
+
+        # If we're not tracing, just return
+        if context is None:
+            return wrapped(*args, **kwargs)
+
+        try:
+            span = instana.internal_tracer.start_span("soap", child_of=context)
+            span.set_tag('soap.action', instance.method.name)
+            span.set_tag(ext.HTTP_URL, instance.method.location)
+            span.set_tag(ext.HTTP_METHOD, 'POST')
+
+            instana.internal_tracer.inject(span.context, opentracing.Format.HTTP_HEADERS,
+                                           instance.options.headers)
+
+            rv = wrapped(*args, **kwargs)
+
+        except Exception as e:
+            span.log_exception(e)
+            span.set_tag(ext.HTTP_STATUS_CODE, 500)
+            raise
+        else:
+            span.set_tag(ext.HTTP_STATUS_CODE, 200)
+            return rv
+        finally:
+            span.finish()
+
+    logger.debug("Instrumenting suds-jurko")
+except ImportError:
+    pass

instana/json_span.py

@@ -22,6 +22,7 @@ class Data(object):
     baggage = None
     custom = None
     sdk = None
+    soap = None
 
     def __init__(self, **kwds):
         self.__dict__.update(kwds)
@@ -36,6 +37,12 @@ class HttpData(object):
     def __init__(self, **kwds):
         self.__dict__.update(kwds)
 
+class SoapData(object):
+    action = None
+
+    def __init__(self, **kwds):
+        self.__dict__.update(kwds)
+
 
 class CustomData(object):
     tags = None

instana/meter.py

@@ -153,12 +153,10 @@ def collect_snapshot(self):
             s = Snapshot(name=appname, version=sys.version)
             s.version = sys.version
             s.versions = self.collect_modules()
-
-            return s
         except Exception as e:
-            log.debug("collect_snapshot: ", str(e))
-
-            return None
+            log.debug(e.message)
+        else:
+            return s
 
     def jsonable(self, value):
         try:
@@ -174,8 +172,8 @@ def jsonable(self, value):
 
     def collect_modules(self):
         try:
-            m = sys.modules
             r = {}
+            m = sys.modules
             for k in m:
                 # Don't report submodules (e.g. django.x, django.y, django.z)
                 if ('.' in k):
@@ -193,11 +191,10 @@ def collect_modules(self):
                         r[k] = "unknown"
                         log.debug("collect_modules: could not process module ", k, str(e))
 
-            return r
         except Exception as e:
-            log.debug("collect_modules: ", str(e))
-
-            return None
+            log.debug(e.message)
+        else:
+            return r
 
     def collect_metrics(self):
         u = resource.getrusage(resource.RUSAGE_SELF)

instana/recorder.py

@@ -6,7 +6,7 @@
 
 import opentracing.ext.tags as ext
 from basictracer import Sampler, SpanRecorder
-from .json_span import CustomData, Data, HttpData, JsonSpan, SDKData
+from .json_span import CustomData, Data, HttpData, SoapData, JsonSpan, SDKData
 from .agent_const import AGENT_TRACES_URL
 
 import sys
@@ -18,9 +18,10 @@
 
 class InstanaRecorder(SpanRecorder):
     sensor = None
-    registered_spans = ("django", "memcache", "rpc-client", "rpc-server", "urllib3", "wsgi")
+    registered_spans = ("django", "memcache", "rpc-client", "rpc-server",
+                        "soap", "urllib3", "wsgi")
     entry_kind = ["entry", "server", "consumer"]
-    exit_kind = ["exit", "client", "producer"]
+    exit_kind = ["exit", "client", "producer", "soap"]
     queue = queue.Queue()
 
     def __init__(self, sensor):
@@ -84,9 +85,11 @@ def build_registered_span(self, span):
                                   url=self.get_string_tag(span, ext.HTTP_URL),
                                   method=self.get_string_tag(span, ext.HTTP_METHOD),
                                   status=self.get_tag(span, ext.HTTP_STATUS_CODE)),
+                    soap=SoapData(action=self.get_tag(span, 'soap.action')),
                     baggage=span.context.baggage,
                     custom=CustomData(tags=span.tags,
                     logs=self.collect_logs(span)))
+
         entityFrom = {'e': self.sensor.agent.from_.pid,
                       'h': self.sensor.agent.from_.agentUuid}
 
@@ -124,6 +127,8 @@ def build_sdk_span(self, span):
                     d=int(round(span.duration * 1000)),
                     n="sdk",
                     f=entityFrom,
+                    # ec=self.get_tag(span, "ec"),
+                    # error=self.get_tag(span, "error"),
                     data=data)
 
     def get_tag(self, span, tag):

instana/span.py

@@ -14,3 +14,15 @@ def finish(self, finish_time=None):
                                sampled=True)
             self.tracer.cur_ctx = pctx
         super(InstanaSpan, self).finish(finish_time)
+
+    def log_exception(self, e):
+        if hasattr(e, 'message'):
+            self.log_kv({'message': e.message})
+        elif hasattr(e, '__str__'):
+            self.log_kv({'message': e.__str__()})
+        else:
+            self.log_kv({'message': str(e)})
+
+        self.set_tag("error", True)
+        ec = self.tags.get('ec', 0)
+        self.set_tag("ec", ec+1)

requirements-test.txt

@@ -0,0 +1,2 @@
+# See setup.py for dependencies
+-e .[test]

requirements.txt

@@ -1,4 +1,2 @@
-fysom>=2.1.2
-opentracing>=1.2.1
-basictracer>=2.2.0
-autowrapt>=1.0
+# See setup.py for dependencies
+-e .

setup.py

@@ -1,28 +1,37 @@
 from setuptools import setup, find_packages
 
 setup(name='instana',
-      version='0.7.12',
-      download_url='https://github.com/instana/python-sensor',
-      url='https://www.instana.com/',
-      license='MIT',
-      author='Instana Inc.',
-      author_email='[email protected]',
-      description='Metrics sensor and trace collector for Instana',
-      packages=find_packages(exclude=['tests', 'examples']),
-      long_description="The instana package provides Python metrics and traces for Instana.",
-      zip_safe=False,
-      setup_requires=['nose>=1.0', 'flask>=0.12.2'],
-      install_requires=['autowrapt>=1.0',
-                        'fysom>=2.1.2',
-                        'opentracing>=1.2.1,<1.3',
-                        'basictracer>=2.2.0'],
-      entry_points={'django': ['django.core.handlers.base = instana.django:hook'],
-                    'django19': ['django.core.handlers.base = instana.django:hook19'],
-                    'flask': ['flask = instana.flaskana:hook'],
-                    'runtime': ['string = instana.runtime:hook']},
-      test_suite='nose.collector',
-      keywords=['performance', 'opentracing', 'metrics', 'monitoring'],
-      classifiers=[
+    version='0.7.12',
+    download_url='https://github.com/instana/python-sensor',
+    url='https://www.instana.com/',
+    license='MIT',
+    author='Instana Inc.',
+    author_email='[email protected]',
+    description='Metrics sensor and trace collector for Instana',
+    packages=find_packages(exclude=['tests', 'examples']),
+    long_description="The instana package provides Python metrics and traces for Instana.",
+    zip_safe=False,
+    install_requires=['autowrapt>=1.0',
+                      'fysom>=2.1.2',
+                      'opentracing>=1.2.1,<1.3',
+                      'basictracer>=2.2.0'],
+    entry_points={'django': ['django.core.handlers.base = instana.django:hook'],
+                  'django19': ['django.core.handlers.base = instana.django:hook19'],
+                  'flask': ['flask = instana.flaskana:hook'],
+                  'runtime': ['string = instana.runtime:hook']},
+    extras_require={
+        'test': [
+            'nose>=1.0',
+            'flask>=0.12.2',
+            'requests>=2.17.1',
+            'spyne>=2.9',
+            'lxml>=3.4',
+            'suds-jurko>=0.6'
+        ],
+    },
+    test_suite='nose.collector',
+    keywords=['performance', 'opentracing', 'metrics', 'monitoring'],
+    classifiers=[
         'Development Status :: 5 - Production/Stable',
         'Framework :: Django',
         'Framework :: Flask',

test_requirements.txt

@@ -3,14 +3,33 @@
 import time
 import threading
 from .apps.flaskalino import app as flaskalino
+from .apps.soapserver4132 import soapserver
+
 os.environ["INSTANA_TEST"] = "true"
 
+
+# Background Flask application
+#
 # Spawn our background Flask app that the tests will throw
 # requests at.  Don't continue until the test app is fully
 # up and running.
 timer = threading.Thread(target=flaskalino.run)
 timer.daemon = True
-timer.name = "Test Flask app"
-print("Starting background test app")
+timer.name = "Background Flask app"
+print("Starting background Flask app...")
 timer.start()
+
+
+# Background Soap Server
+#
+# Spawn our background Flask app that the tests will throw
+# requests at.  Don't continue until the test app is fully
+# up and running.
+timer = threading.Thread(target=soapserver.serve_forever)
+timer.daemon = True
+timer.name = "Background Soap server"
+print("Starting background Soap server...")
+timer.start()
+
+
 time.sleep(1)

tests/__init__.py

@@ -0,0 +1,55 @@
+# vim: set fileencoding=UTF-8 :
+import logging
+from spyne import Application, rpc, ServiceBase, Iterable, Integer, Unicode, Fault
+from spyne.protocol.soap import Soap11
+from spyne.server.wsgi import WsgiApplication
+from wsgiref.simple_server import make_server
+from instana.wsgi import iWSGIMiddleware
+
+# Simple in test suite SOAP server to test suds client instrumentation against.
+# Configured to listen on localhost port 4132
+# WSDL: http://localhost:4232/?wsdl
+
+class StanSoapService(ServiceBase):
+    @rpc(Unicode, Integer, _returns=Iterable(Unicode))
+    def ask_question(ctx, question, answer):
+        """Ask Stan a question!
+        <b>Ask Stan questions as a Service</b>
+
+        @param name the name to say hello to
+        @param times the number of times to say hello
+        @return the completed array
+        """
+
+        yield u'To an artificial mind, all reality is virtual. How do they know that the real world isn\'t just another simulation? How do you?'
+
+
+    @rpc()
+    def server_exception(ctx):
+        raise Exception("Server side exception example.")
+
+    @rpc()
+    def server_fault(ctx):
+        raise Fault("Server", "Server side fault example.")
+
+    @rpc()
+    def client_fault(ctx):
+        raise Fault("Client", "Client side fault example")
+
+
+
+app = Application([StanSoapService], 'instana.tests.app.ask_question',
+                  in_protocol=Soap11(validator='lxml'), out_protocol=Soap11())
+
+# Use Instana middleware so we can test context passing and Soap server traces.
+wsgi_app = iWSGIMiddleware(WsgiApplication(app))
+soapserver = make_server('127.0.0.1', 4132, wsgi_app)
+
+logging.basicConfig(level=logging.WARN)
+logging.getLogger('suds').setLevel(logging.WARN)
+logging.getLogger('suds.resolver').setLevel(logging.WARN)
+logging.getLogger('spyne.protocol.xml').setLevel(logging.WARN)
+logging.getLogger('spyne.model.complex').setLevel(logging.WARN)
+
+if __name__ == '__main__':
+    soapserver.serve_forever()