[Fix][Plugin] sw_flask general exceptions handled

[tom-pytel]

• sw_flask fix will handle errors like returning the wrong type from a handler or other internal errors.
• Updated StackedSpan to track depth, and made depth variable instance instead of class level (this was a bug).
• Changed how SpanContext decides when all spans finished to write Segment data, now counts span start / stops which should work better across different async scenarios.
• Changed new_exit_span() with span.inject() to work simpler like the NodeJS agent, now plugins inject directly themselves if they need to.
• Removed carrier from plugins which didn't actually use it.

[tom-pytel]

??? 😕

[tom-pytel]

Just a random question but ... why are the meanings of span.inject() and span.extract() inverted between the Python and Node agents? Which one has it right?

[tom-pytel]

Question about SpanContext.new_entry_span() and .new_exit_span(), should span.inject() / .extract() be called on every call to new_? as it is now or only when the Span is created for the first time?

[kezhenxu94]

Just a random question but ... why are the meanings of span.inject() and span.extract() inverted between the Python and Node agents? Which one has it right?

Python has it right.

Question about SpanContext.new_entry_span() and .new_exit_span(), should span.inject() / .extract() be called on every call to new_? as it is now or only when the Span is created for the first time?

Should be called on every call to new_{entry,exit}_span}, this is for cross-service context propagation, otherwise, the traces would break into pieces (per service)

[tom-pytel]

Question about SpanContext.new_entry_span() and .new_exit_span(), should span.inject() / .extract() be called on every call to new_? as it is now or only when the Span is created for the first time?

Should be called on every call to new_{entry,exit}_span}, this is for cross-service context propagation, otherwise, the traces would break into pieces (per service)

I understand the that this links an exit span to another service entry but the reason I ask is that multiple entry or exit spans share a single actual span which is only created once. So for example a flask entry span on top of an http server entry span is still only a single span but with a depth of 2, so does the second span.extract() for the flask entry span actually change the trace or span or segment ID or any information like that, because unless I am missing something it looks redundant?

[tom-pytel]

Hmm, 3.5 configuration issue?

[kezhenxu94]

Hmm, 3.5 configuration issue?

Might not be conf issue, suspect it’s some external changes like Pypi dependency or anything that needs to look into, will take a look

[tom-pytel]

So if you are going to remove 3.5 can you merge this anyway?

[kezhenxu94]

So if you are going to remove 3.5 can you merge this anyway?

We've set it required so that we need to remove the require first otherwise the GitHub doesn't allow us to merge, please wait a little bit for #95 , after that this can be merged immediately

[tom-pytel]

• Changed new_exit_span() with span.inject() to work simpler like the NodeJS agent, now plugins inject directly themselves if they need to.
• Removed carrier from plugins which didn't actually use it.

I am getting strange random test failures with django 2.0, the request may succeed or it may get the span stored 2, 3 or even 4 times, but only django 2.0. Am looking into it: [EDIT] this seems to be a result of my dirty local environment since it seems to work just fine here (twice already):

=========================================================== test session starts ============================================================
platform linux -- Python 3.8.6, pytest-6.1.2, py-1.9.0, pluggy-0.13.1 -- /home/tom/src/revdebugpy/debug38/.venvdebug38/bin/python3
cachedir: .pytest_cache
rootdir: /home/tom/src/revdebugpy/skywalking-python
collected 37 items

tests/test_ant_matcher.py::TestFastPathMatch::test_match PASSED                                                                      [  2%]
tests/test_counter.py::TestAtomicCounter::test_counter PASSED                                                                        [  5%]
tests/test_version_check.py::TestVersionCheck::test_operators PASSED                                                                 [  8%]
tests/test_version_check.py::TestVersionCheck::test_version_check PASSED                                                             [ 10%]
tests/plugin/sw_django/test_django.py::TestPlugin::test_plugin[django==2.0] FAILED                                                   [ 13%]
tests/plugin/sw_django/test_django.py::TestPlugin::test_plugin[django==2.2] PASSED                                                   [ 16%]
tests/plugin/sw_django/test_django.py::TestPlugin::test_plugin[django==3.0] PASSED                                                   [ 18%]
tests/plugin/sw_django/test_django.py::TestPlugin::test_plugin[django==3.1] PASSED                                                   [ 21%]
tests/plugin/sw_elasticsearch/test_elasticsearch.py::TestPlugin::test_plugin[elasticsearch==7.9.0] PASSED                            [ 24%]
tests/plugin/sw_flask/test_flask.py::TestPlugin::test_plugin[flask==1.1.2] PASSED                                                    [ 27%]
tests/plugin/sw_flask/test_flask.py::TestPlugin::test_plugin[flask==1.0.4] PASSED                                                    [ 29%]
tests/plugin/sw_http/test_http.py::TestPlugin::test_plugin PASSED                                                                    [ 32%]
tests/plugin/sw_http_wsgi/test_http_wsgi.py::TestPlugin::test_plugin[werkzeug==1.0.1] PASSED                                         [ 35%]
tests/plugin/sw_kafka/test_kafka.py::TestPlugin::test_plugin[kafka-python==2.0.1] PASSED                                             [ 37%]
tests/plugin/sw_process/test_process.py::TestPlugin::test_plugin PASSED                                                              [ 40%]
tests/plugin/sw_pymongo/test_pymongo.py::TestPlugin::test_plugin[pymongo==3.11.0] PASSED                                             [ 43%]
tests/plugin/sw_pymysql/test_pymysql.py::TestPlugin::test_plugin[PyMySQL==0.10.0] PASSED                                             [ 45%]
tests/plugin/sw_rabbitmq/test_rabbitmq.py::TestPlugin::test_plugin[pika==1.1.0] PASSED                                               [ 48%]
tests/plugin/sw_redis/test_redis.py::TestPlugin::test_plugin[redis==3.5.3] PASSED                                                    [ 51%]
tests/plugin/sw_requests/test_request.py::TestPlugin::test_plugin[requests==2.24.0] PASSED                                           [ 54%]
tests/plugin/sw_requests/test_request.py::TestPlugin::test_plugin[requests==2.20.0] PASSED                                           [ 56%]
tests/plugin/sw_requests/test_request.py::TestPlugin::test_plugin[requests==2.19.0] PASSED                                           [ 59%]
tests/plugin/sw_requests/test_request.py::TestPlugin::test_plugin[requests==2.18.0] PASSED                                           [ 62%]
tests/plugin/sw_requests/test_request.py::TestPlugin::test_plugin[requests==2.17.0] PASSED                                           [ 64%]
tests/plugin/sw_requests/test_request.py::TestPlugin::test_plugin[requests==2.13.0] PASSED                                           [ 67%]
tests/plugin/sw_requests/test_request.py::TestPlugin::test_plugin[requests==2.11.0] PASSED                                           [ 70%]
tests/plugin/sw_requests/test_request.py::TestPlugin::test_plugin[requests==2.9.0] PASSED                                            [ 72%]
tests/plugin/sw_sanic/test_sanic.py::TestPlugin::test_plugin[sanic==20.3.0] PASSED                                                   [ 75%]
tests/plugin/sw_sanic/test_sanic.py::TestPlugin::test_plugin[sanic==20.6.0] PASSED                                                   [ 78%]
tests/plugin/sw_sanic/test_sanic.py::TestPlugin::test_plugin[sanic==20.6.1] PASSED                                                   [ 81%]
tests/plugin/sw_sanic/test_sanic.py::TestPlugin::test_plugin[sanic==20.6.2] PASSED                                                   [ 83%]
tests/plugin/sw_sanic/test_sanic.py::TestPlugin::test_plugin[sanic==20.6.3] PASSED                                                   [ 86%]
tests/plugin/sw_sanic/test_sanic.py::TestPlugin::test_plugin[sanic==20.9.0] PASSED                                                   [ 89%]
tests/plugin/sw_sanic/test_sanic.py::TestPlugin::test_plugin[sanic==20.9.1] PASSED                                                   [ 91%]
tests/plugin/sw_tornado/test_tornado.py::TestPlugin::test_plugin[tornado==6.0.4] PASSED                                              [ 94%]
tests/plugin/sw_urllib3/test_urllib3.py::TestPlugin::test_plugin[urllib3==1.25.10] PASSED                                            [ 97%]
tests/plugin/sw_urllib3/test_urllib3.py::TestPlugin::test_plugin[urllib3==1.25.9] PASSED                                             [100%]

================================================================= FAILURES =================================================================
___________________________________________________ TestPlugin.test_plugin[django==2.0] ____________________________________________________

self = <tests.plugin.sw_django.test_django.TestPlugin object at 0x7f9e1a111820>
docker_compose = <testcontainers.compose.DockerCompose object at 0x7f9e1a117370>, version = 'django==2.0'

    @pytest.mark.parametrize('version', [
        'django==2.0',
        'django==2.2',
        'django==3.0',
        'django==3.1',
    ])
    def test_plugin(self, docker_compose, version):
>       self.validate()

tests/plugin/sw_django/test_django.py:39:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

self = <tests.plugin.sw_django.test_django.TestPlugin object at 0x7f9e1a111820>
expected_file_name = '/home/tom/src/revdebugpy/skywalking-python/tests/plugin/sw_django/expected.data.yml'

    def validate(self, expected_file_name=None):
        # type: (str) -> Response

        if expected_file_name is None:
            expected_file_name = os.path.join(dirname(inspect.getfile(self.__class__)), 'expected.data.yml')

        time.sleep(10)

        with open(expected_file_name) as expected_data_file:
            expected_data = os.linesep.join(expected_data_file.readlines())

            response = requests.post(url='http://0.0.0.0:12800/dataValidate', data=expected_data)

            if response.status_code != 200:
                res = requests.get('http://0.0.0.0:12800/receiveData')

                actual_data = yaml.dump(yaml.load(res.content, Loader=Loader))

                differ = Differ()
                diff_list = list(differ.compare(
                    actual_data.splitlines(keepends=True),
                    yaml.dump(yaml.load(expected_data, Loader=Loader)).splitlines(keepends=True)
                ))

                print('diff list: ')

                sys.stdout.writelines(diff_list)

>           assert response.status_code == 200
E           AssertionError

tests/plugin/base.py:65: AssertionError
---------------------------------------------------------- Captured stderr setup -----------------------------------------------------------
sw_django_collector_1 is up-to-date
Starting sw_django_provider_1 ... done
Starting sw_django_consumer_1 ... done

----------------------------------------------------------- Captured stdout call -----------------------------------------------------------
diff list:
  segmentItems:
- - segmentSize: 3
?                ^
+ - segmentSize: 1
?                ^
    segments:
-   - segmentId: 76b5a166397311eb8e980242ac130003
+   - segmentId: not null
      spans:
      - componentId: 7004
+       endTime: gt 0
-       endTime: 1607445364557
-       isError: false
        operationId: 0
        operationName: /users
        parentSpanId: -1
-       peer: 172.19.0.4:80
+       peer: not null
        refs:
        - networkAddress: provider:9091
          parentEndpoint: /users
          parentService: consumer
-         parentServiceInstance: 72ff6dae397311eb8fbe0242ac130004
+         parentServiceInstance: not null
          parentSpanId: 1
-         parentTraceSegmentId: 76b5126e397311eb8e9b0242ac130004
+         parentTraceSegmentId: not null
          refType: CrossProcess
-         traceId: 76b5137c397311eb8e9b0242ac130004
+         traceId: not null
        skipAnalysis: false
        spanId: 0
        spanLayer: Http
        spanType: Entry
+       startTime: gt 0
-       startTime: 1607445364057
-       tags:
-       - key: http.method
-         value: POST
-       - key: url
-         value: http://provider:9091/users
-       - key: status.code
-         value: '200'
-   - segmentId: cfc80b1a397611eba5ba0242ac130003
-     spans:
-     - componentId: 7004
-       endTime: 1607446802485
-       isError: false
-       operationId: 0
-       operationName: /users
-       parentSpanId: -1
-       peer: 172.19.0.4:80
-       refs:
-       - networkAddress: provider:9091
-         parentEndpoint: /users
-         parentService: consumer
-         parentServiceInstance: ca2ba9e6397611eb98830242ac130004
-         parentSpanId: 1
-         parentTraceSegmentId: cfc79d6a397611eb88ab0242ac130004
-         refType: CrossProcess
-         traceId: cfc79e46397611eb88ab0242ac130004
-       skipAnalysis: false
-       spanId: 0
-       spanLayer: Http
-       spanType: Entry
-       startTime: 1607446801985
-       tags:
-       - key: http.method
-         value: POST
-       - key: url
-         value: http://provider:9091/users
-       - key: status.code
-         value: '200'
-   - segmentId: 53216d3a397711eb9a8f0242ac130003
-     spans:
-     - componentId: 7004
-       endTime: 1607447022855
-       isError: false
-       operationId: 0
-       operationName: /users
-       parentSpanId: -1
-       peer: 172.19.0.4:80
-       refs:
-       - networkAddress: provider:9091
-         parentEndpoint: /users
-         parentService: consumer
-         parentServiceInstance: 4d85a620397711eb9d270242ac130004
-         parentSpanId: 1
-         parentTraceSegmentId: 5320e18a397711eba6510242ac130004
-         refType: CrossProcess
-         traceId: 5320e2a2397711eba6510242ac130004
-       skipAnalysis: false
-       spanId: 0
-       spanLayer: Http
-       spanType: Entry
-       startTime: 1607447022352
        tags:
        - key: http.method
          value: POST
        - key: url
          value: http://provider:9091/users
        - key: status.code
          value: '200'
    serviceName: provider
- - segmentSize: 3
?                ^
+ - segmentSize: 1
?                ^
    segments:
-   - segmentId: 76b5126e397311eb8e9b0242ac130004
+   - segmentId: not null
      spans:
      - componentId: 7002
+       endTime: gt 0
-       endTime: 1607445364559
-       isError: false
        operationId: 0
        operationName: /users
        parentSpanId: 0
        peer: provider:9091
        skipAnalysis: false
        spanId: 1
        spanLayer: Http
        spanType: Exit
-       startTime: 1607445364053
+       startTime: gt 0
        tags:
        - key: http.method
          value: POST
        - key: url
          value: http://provider:9091/users
        - key: status.code
          value: '200'
      - componentId: 7004
+       endTime: gt 0
-       endTime: 1607445364559
-       isError: false
        operationId: 0
        operationName: /users
        parentSpanId: -1
-       peer: 172.19.0.1:80
+       peer: not null
        skipAnalysis: false
        spanId: 0
        spanLayer: Http
        spanType: Entry
+       startTime: gt 0
-       startTime: 1607445364053
-       tags:
-       - key: http.method
-         value: GET
-       - key: url
-         value: http://0.0.0.0:9090/users
-       - key: http.params
-         value: 'test=[test1,test2]
-
-           test2=[test2]'
-       - key: status.code
-         value: '200'
-   - segmentId: cfc79d6a397611eb88ab0242ac130004
-     spans:
-     - componentId: 7002
-       endTime: 1607446802487
-       isError: false
-       operationId: 0
-       operationName: /users
-       parentSpanId: 0
-       peer: provider:9091
-       skipAnalysis: false
-       spanId: 1
-       spanLayer: Http
-       spanType: Exit
-       startTime: 1607446801982
-       tags:
-       - key: http.method
-         value: POST
-       - key: url
-         value: http://provider:9091/users
-       - key: status.code
-         value: '200'
-     - componentId: 7004
-       endTime: 1607446802487
-       isError: false
-       operationId: 0
-       operationName: /users
-       parentSpanId: -1
-       peer: 172.19.0.1:80
-       skipAnalysis: false
-       spanId: 0
-       spanLayer: Http
-       spanType: Entry
-       startTime: 1607446801982
-       tags:
-       - key: http.method
-         value: GET
-       - key: url
-         value: http://0.0.0.0:9090/users
-       - key: http.params
-         value: 'test=[test1,test2]
-
-           test2=[test2]'
-       - key: status.code
-         value: '200'
-   - segmentId: 5320e18a397711eba6510242ac130004
-     spans:
-     - componentId: 7002
-       endTime: 1607447022856
-       isError: false
-       operationId: 0
-       operationName: /users
-       parentSpanId: 0
-       peer: provider:9091
-       skipAnalysis: false
-       spanId: 1
-       spanLayer: Http
-       spanType: Exit
-       startTime: 1607447022349
-       tags:
-       - key: http.method
-         value: POST
-       - key: url
-         value: http://provider:9091/users
-       - key: status.code
-         value: '200'
-     - componentId: 7004
-       endTime: 1607447022856
-       isError: false
-       operationId: 0
-       operationName: /users
-       parentSpanId: -1
-       peer: 172.19.0.1:80
-       skipAnalysis: false
-       spanId: 0
-       spanLayer: Http
-       spanType: Entry
-       startTime: 1607447022348
        tags:
        - key: http.method
          value: GET
        - key: url
          value: http://0.0.0.0:9090/users
        - key: http.params
          value: 'test=[test1,test2]

            test2=[test2]'
        - key: status.code
          value: '200'
    serviceName: consumer
--------------------------------------------------------- Captured stderr teardown ---------------------------------------------------------
Stopping sw_django_consumer_1  ... done
Stopping sw_django_provider_1  ... done
Stopping sw_django_collector_1 ... done
Removing sw_django_consumer_1  ... done
Removing sw_django_provider_1  ... done
Removing sw_django_collector_1 ... done
Removing network sw_django_beyond
========================================================= short test summary info ==========================================================
FAILED tests/plugin/sw_django/test_django.py::TestPlugin::test_plugin[django==2.0] - AssertionError
================================================ 1 failed, 36 passed in 1778.11s (0:29:38) =================================================

[tom-pytel]

Need to check something with you, I am thinking to change the behavior of SW_TRACE_IGNORE and SW_TRACE_IGNORE_PATH to simplify it to work like in the Node agent. That is - remove SW_TRACE_IGNORE and enable trace ignore on the presence of a non-empty SW_TRACE_IGNORE_PATH variable.

I am checking with you first because this would change behavior (slightly, currently SW_TRACE_IGNORE only checks against "True" and even case-sensitive so is not very robust). But it is a simplification and consistent with the other dynamic language agent (Node). So do you have any problem with me changing this?

[kezhenxu94]

Need to check something with you, I am thinking to change the behavior of SW_TRACE_IGNORE and SW_TRACE_IGNORE_PATH to simplify it to work like in the Node agent. That is - remove SW_TRACE_IGNORE and enable trace ignore on the presence of a non-empty SW_TRACE_IGNORE_PATH variable.

I’m +1 to this change.

So do you have any problem with me changing this?

No problem. Go ahead.

[kezhenxu94]

LGTM, merging, please open another PR (if needed) for aforementioned enhancements, thanks