Better boot behaviour; Respect load dynamics (#98)

* Better boot behaviour:

- Longer delay before attempting host agent discovery
- Clean-up and add start methods hooked to a Timer

* Function documentation

* If being loaded dynamically, delay instrumentation load

Author: pglombardo

instana/__init__.py

@@ -2,6 +2,7 @@
 
 import os
 import pkg_resources
+from threading import Timer
 
 
 """
@@ -54,9 +55,18 @@ def load(module):
 
 import instana.singletons #noqa
 
-if "INSTANA_DISABLE_AUTO_INSTR" not in os.environ:
-    # Import & initialize instrumentation
-    from .instrumentation import urllib3  # noqa
-    from .instrumentation import sudsjurko  # noqa
-    from .instrumentation import mysqlpython  # noqa
-    from .instrumentation.django import middleware  # noqa
+def load_instrumentation():
+    if "INSTANA_DISABLE_AUTO_INSTR" not in os.environ:
+        # Import & initialize instrumentation
+        from .instrumentation import urllib3  # noqa
+        from .instrumentation import sudsjurko  # noqa
+        from .instrumentation import mysqlpython  # noqa
+        from .instrumentation.django import middleware  # noqa
+
+if "INSTANA_MAGIC" in os.environ:
+    # If we're being loaded into an already running process, then delay
+    # instrumentation load.
+    t = Timer(2.0, load_instrumentation)
+    t.start()
+else:
+    load_instrumentation()

instana/agent.py

@@ -5,11 +5,12 @@
 import threading
 from datetime import datetime
 
-from .log import logger
+import instana.singletons
+
 from .agent_const import AGENT_DEFAULT_HOST, AGENT_DEFAULT_PORT
 from .fsm import Fsm
+from .log import logger
 from .sensor import Sensor
-import instana.singletons
 
 try:
     import urllib.request as urllib2
@@ -52,6 +53,12 @@ def __init__(self):
         self.sensor = Sensor(self)
         self.fsm = Fsm(self)
 
+    def start(self, e):
+        """ Starts the agent and required threads """
+        logger.debug("Spawning metric & trace reporting threads")
+        self.sensor.meter.run()
+        instana.singletons.tracer.recorder.run()
+
     def to_json(self, o):
         try:
             return json.dumps(o, default=lambda o: {k.lower(): v for k, v in o.__dict__.items()},
@@ -125,6 +132,7 @@ def full_request_response(self, url, method, o, body, header):
 
                     if method == "HEAD":
                         b = True
+                    # logger.warn("%s %s --> response: %s" % (method, url, b))
         except Exception as e:
             # No need to show the initial 404s or timeouts.  The agent
             # should handle those correctly.

instana/fsm.py

@@ -64,13 +64,13 @@ def __init__(self, agent):
             "callbacks": {
                 "onlookup":       self.lookup_agent_host,
                 "onannounce":     self.announce_sensor,
-                "onready":        self.start_metric_reporting,
+                "onready":        self.agent.start,
                 "onchangestate":  self.printstatechange}})
 
-        timer = t.Timer(2, self.fsm.lookup)
-        timer.daemon = True
-        timer.name = "Startup"
-        timer.start()
+        self.timer = t.Timer(5, self.fsm.lookup)
+        self.timer.daemon = True
+        self.timer.name = "Startup"
+        self.timer.start()
 
     def printstatechange(self, e):
         logger.debug('========= (%i#%s) FSM event: %s, src: %s, dst: %s ==========' %
@@ -79,9 +79,6 @@ def printstatechange(self, e):
     def reset(self):
         self.fsm.lookup()
 
-    def start_metric_reporting(self, e):
-        self.agent.sensor.meter.run()
-
     def lookup_agent_host(self, e):
         host, port = self.__get_agent_host_port()
 

instana/meter.py

@@ -123,19 +123,22 @@ def __init__(self, agent):
         pass
 
     def run(self):
+        """ Spawns the metric reporting thread """
         self.thr = threading.Thread(target=self.collect_and_report)
         self.thr.daemon = True
         self.thr.name = "Instana Metric Collection"
         self.thr.start()
 
     def reset(self):
+        """" Reset the state as new """
         self.last_usage = None
         self.last_collect = None
         self.last_metrics = None
         self.run()
 
     def collect_and_report(self):
-        log.debug("starting metric reporting thread")
+        """ Target function for the metric reporting thread """
+        log.debug("Metric reporting thread is now alive")
         while 1:
             self.process()
             if self.agent.is_timed_out():
@@ -145,6 +148,7 @@ def collect_and_report(self):
             time.sleep(1)
 
     def process(self):
+        """ Collects, processes & reports metrics """
         if self.agent.can_send():
             self.snapshot_countdown = self.snapshot_countdown - 1
             ss = None
@@ -163,6 +167,7 @@ def process(self):
             self.last_metrics = cm.__dict__
 
     def collect_snapshot(self):
+        """  Collects snapshot related information to this process and environment """
         try:
             if "FLASK_APP" in os.environ:
                 appname = os.environ["FLASK_APP"]
@@ -200,6 +205,7 @@ def jsonable(self, value):
             log.debug(e)
 
     def collect_modules(self):
+        """ Collect up the list of modules in use """
         try:
             res = {}
             m = sys.modules
@@ -228,6 +234,7 @@ def collect_modules(self):
             return res
 
     def collect_metrics(self):
+        """ Collect up and return various metrics """
         u = resource.getrusage(resource.RUSAGE_SELF)
         if gc_.isenabled():
             c = list(gc_.get_count())

instana/recorder.py

@@ -14,6 +14,7 @@
 from .agent_const import AGENT_TRACES_URL
 from .json_span import (CustomData, Data, HttpData, JsonSpan, MySQLData,
                         SDKData, SoapData)
+from .log import logger
 
 if sys.version_info.major is 2:
     import Queue as queue
@@ -31,7 +32,6 @@ class InstanaRecorder(SpanRecorder):
 
     def __init__(self):
         super(InstanaRecorder, self).__init__()
-        self.run()
 
     def run(self):
         """ Span a background thread to periodically report queued spans """
@@ -42,6 +42,7 @@ def run(self):
 
     def report_spans(self):
         """ Periodically report the queued spans """
+        logger.debug("Span reporting thread is now alive")
         while 1:
             if self.queue.qsize() > 0 and instana.singletons.agent.can_send():
                 url = instana.singletons.agent.make_url(AGENT_TRACES_URL)