/cc @bogdandrutu

Hi @odeke-em, seems like you are using an older version of opencensus. Could you try the latest version 0.1.5 to see if the problem still exists?

Thanks @liyanhui1228. Interestingly I had downloaded the latest from Github and was using it after running python3 setup.py install but anyways I deleted all installations by rm -rf /usr/local/lib/python3.6/site-packages/opencensus* and started afresh.

However, now the gRPC interceptor doesn't seem to be creating the parent span grpc_server. I now see this

yet with 0.1.3 I was seeing at least

And yes, I was able to reproduce it again just now by running multiple clients that clash e.g to the client.py I fed them a ~0.5MB file and made this

#!/usr/bin/env python3

# Copyright 2018, OpenCensus Authors
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
#     http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.

import time
import random
import grpc

import defs_pb2_grpc as proto
import defs_pb2 as pb

def main():
    channel = grpc.insecure_channel('localhost:9778')
    stub = proto.FetchStub(channel)

    f = open('gulliversTravels.txt').read().split('\n')
    while True:
        lines = random.sample(f, 10)
        for lineIn in lines:
            capitalized = stub.Capitalize(pb.Payload(data=bytes(lineIn, encoding='utf-8')))
            print('< %s\n'%(capitalized.data.decode('utf-8')))

        time.sleep(random.random() * 8)

if __name__ == '__main__':
    main()

to give

so the problem persists even on opencensus-python [0.1.5]

And actually able to produce many of them in succession

And for a comparison, for about 15 minutes, I've been running the Java gRPC server https://github.com/orijtech/opencensus-for-grpc-java-developers receiving about 14 concurrent requests from the Python client with no problem at all, it produces the right results, right span names too

I think this is due to a bug in how SpanDatas are converted into the legacy trace json format. This line incorrectly assumes that all spans passed to it are part of the same trace.

We should either:

1. Update the exporters to use the Span Data objects directly, bypassing the legacy trace json format conversion
2. Group the spans in the exporter by trace id before formatting them to the legacy trace json format.

I'm OOO right now, but I can probably grab this when I get back.

@odeke-em I think the problem is that in here a tracer is created, which will replace the tracer created by the interceptor in the thread local context. Thus the spans generated by the server interceptor is never exported. Changing that line to tracer = execution_context.get_opencensus_tracer() which reuses the tracer of the interceptor will generate the spans same as the Java one.

I have been tracking down an issue that sounds like it is exactly what @wkiser describes. The problem in my case is made much worse by using the BackgroundThreadTransport which virtually guarantees spans get mashed into exporter submissions for the wrong trace id

So this is a GIGANTIC kludge and not even worth opening a PR over but I modified background_thread.py _Worker._thread_main() with the following to fix the mixed up spans issue:

    def _thread_main(self):
        print('Background thread started.')

        quit_ = False

        while True:
            items = self._get_items()

            current_group = None
            current_group_trace_id  = None
            span_datas_grouped = []

            for item in items:
                if item is _WORKER_TERMINATOR:
                    quit_ = True
                    # Continue processing items, don't break, try to process
                    # all items we got back before quitting.
                else:
                    for actual_item in item:
                        if current_group_trace_id is None or actual_item.context.trace_id != current_group_trace_id:
                            current_group_trace_id = actual_item.context.trace_id
                            current_group = []
                            span_datas_grouped.append(current_group)

                        current_group.append(actual_item)

            if span_datas_grouped:
                for group in span_datas_grouped:
                    if group:
                        self.exporter.emit(group)

            for _ in range(len(items)):
                self._queue.task_done()

            # Wait for a while before next export
            time.sleep(_WAIT_PERIOD)

            if quit_:
                break

        print('Background thread exited.')

Just throwing it out there - may or may not be useful. As a side note, I also feel like _WAIT_PERIOD should be way lower (like 0.1) given that the implementation is already blocking on at least 1 item from the queue. As of right now its limited to 10 submissions per second (assume zero API latency which is obviously not true) and the queue is unbounded (which is never fun)

@odeke-em I think the problem is that in here a tracer is created, which will replace the tracer created by the interceptor in the thread local context. Thus the spans generated by the server interceptor is never exported. Changing that line to tracer = execution_context.get_opencensus_tracer() which reuses the tracer of the interceptor will generate the spans same as the Java one.

Thank you for the response @liyanhui1228 and my apologies for the late reply, I've been swamped that I forgot to check here. I've tried just that right now but unfortunately the same problem even after trying out the change orijtech/opencensus-for-grpc-python-developers@93a5392
as well as a variant of it where at the beginning, before the gRPC server is created, a tracer is inserted into the execution_context.

Please let me know what y'all think? I believe @wkiser and @dhendry have made some postulates in here that we could also try.

Above is the latest output even after the change

I am experiencing the same issue here as well, any update on a fix?

It seems like the span context trace id for each trace is the same. Is this expected? For example I'm outputting this trace data when adding a print sds log here: https://github.com/census-instrumentation/opencensus-python/blob/master/opencensus/trace/exporters/stackdriver_exporter.py#L222

[_SpanData(name='some span name', context=SpanContext(trace_id=a0316c0b98264b13b6a153a9c11c2776, span_id=None, trace_options=TraceOptions(enabled=True), tracestate=None), span_id='6adf9edc3f7048dd', parent_span_id=None, attributes={'error.message': None, 'component': 'grpc'}, start_time='2019-02-06T19:56:23.557920Z', end_time='2019-02-06T19:56:23.734099Z', child_span_count=0, stack_trace=None, time_events=[<opencensus.trace.time_event.TimeEvent object at 0x10b8d5490>, <opencensus.trace.time_event.TimeEvent object at 0x10b8d5910>], links=[], status=None, same_process_as_parent_span=None, span_kind=2)]
[_SpanData(name='some span name', context=SpanContext(trace_id=a0316c0b98264b13b6a153a9c11c2776, span_id=0c9182e95ff340b1, trace_options=TraceOptions(enabled=True), tracestate=None), span_id='0c9182e95ff340b1', parent_span_id='6adf9edc3f7048dd', attributes={'error.message': None, 'component': 'grpc'}, start_time='2019-02-06T19:56:39.421969Z', end_time='2019-02-06T19:56:39.582180Z', child_span_count=0, stack_trace=None, time_events=[<opencensus.trace.time_event.TimeEvent object at 0x10b9d05d0>, <opencensus.trace.time_event.TimeEvent object at 0x10b9d0210>], links=[], status=None, same_process_as_parent_span=None, span_kind=2), 
_SpanData(name='some span name', context=SpanContext(trace_id=a0316c0b98264b13b6a153a9c11c2776, span_id=0c9182e95ff340b1, trace_options=TraceOptions(enabled=True), tracestate=None), span_id='506fb62adb1b4a2d', parent_span_id='0c9182e95ff340b1', attributes={'error.message': None, 'component': 'grpc'}, start_time='2019-02-06T19:57:17.174536Z', end_time='2019-02-06T19:57:17.298549Z', child_span_count=0, stack_trace=None, time_events=[<opencensus.trace.time_event.TimeEvent object at 0x10b8f73d0>, <opencensus.trace.time_event.TimeEvent object at 0x10b9d0a50>], links=[], status=None, same_process_as_parent_span=None, span_kind=2)]

Maybe my consumer code is incorrect?

import grpc
from google.cloud.trace.client import Client as TraceClient
from opencensus.trace.tracer import Tracer
from opencensus.trace.exporters.stackdriver_exporter import StackdriverExporter
from opencensus.common.transports.async_ import AsyncTransport
from opencensus.trace.ext.grpc.client_interceptor import OpenCensusClientInterceptor

client = TraceClient.from_service_account_json("/some/service/account/file.json")
exporter = StackdriverExporter(client=client, transport=AsyncTransport)
tracer = Tracer(exporter=exporter)
opencensus_interceptor = OpenCensusClientInterceptor(tracer=tracer)
grpc_channel = grpc.secure_channel("%s:%d" % (address, port), creds)
grpc_channel = grpc.intercept_channel(grpc_channel, opencensus_interceptor)

After more debugging, it seems like the tracer instance holds on to the same span context throughout its lifetime. I never see the span context get refreshed with a new trace id. Shouldn't the tracer be creating a new span context for each new trace? Or should a new tracer be created on each trace?

@wkiser @liyanhui1228

Okay so it seems like the issue I'm experiencing is related to using the tornado web framework in conjunction with the opencensus interceptor. I've added an example to reproduce the issue I'm experiencing here: https://github.com/tab1293/opencensus-python/blob/a3bd681ab27fa161c6b398e43483d2385c85ee15/examples/trace/grpc/hello_world_tornado_client.py

Running this example produces a trace that looks like this:

I'm wondering if this issue has to do something with how threading is handled in this module? The example provided is not using the async transporter FWIW. Any help is appreciated, I'd be more that happy to provide a fix!

Edit: It seems like you can also reproduce without tornado by just wrapping calls in a loop...

diff --git a/examples/trace/grpc/hello_world_client.py b/examples/trace/grpc/hello_world_client.py
index 5752790..bc7037c 100644
--- a/examples/trace/grpc/hello_world_client.py
+++ b/examples/trace/grpc/hello_world_client.py
@@ -35,8 +35,9 @@ def main():
     channel = grpc.insecure_channel(HOST_PORT)
     channel = grpc.intercept_channel(channel, tracer_interceptor)
     stub = hello_world_pb2_grpc.GreeterStub(channel)
-    response = stub.SayHello(hello_world_pb2.HelloRequest(name='you'))
-    print("Message received: " + response.message)
+    for i in range(5):
+        response = stub.SayHello(hello_world_pb2.HelloRequest(name='you'))
+        print("Message received: " + response.message)


 if __name__ == '__main__':

Gives this trace with all separate calls packed in to one trace:

Hey @tab1293, thanks for the detailed report.

After more debugging, it seems like the tracer instance holds on to the same span context throughout its lifetime. I never see the span context get refreshed with a new trace id.

This looks like the problem to me. I would expect that after closing the root span we'd refresh the context and get a new trace ID, but instead we just null out the current context's span ID:

So we're keeping the same trace ID around for the lifetime of the tracer. If you use a new tracer for each request everything works as expected:

diff --git a/examples/trace/grpc/hello_world_client.py b/examples/trace/grpc/hello_world_client.py
index 5752790..14a9404 100644
--- a/examples/trace/grpc/hello_world_client.py
+++ b/examples/trace/grpc/hello_world_client.py
@@ -28,15 +28,15 @@ HOST_PORT = 'localhost:50051'

 def main():
     exporter = stackdriver_exporter.StackdriverExporter()
-    tracer = Tracer(exporter=exporter)
-    tracer_interceptor = client_interceptor.OpenCensusClientInterceptor(
-        tracer,
-        host_port=HOST_PORT)
-    channel = grpc.insecure_channel(HOST_PORT)
-    channel = grpc.intercept_channel(channel, tracer_interceptor)
-    stub = hello_world_pb2_grpc.GreeterStub(channel)
-    response = stub.SayHello(hello_world_pb2.HelloRequest(name='you'))
-    print("Message received: " + response.message)
+    for ii in range(5):
+        tracer = Tracer(exporter=exporter)
+        tracer_interceptor = client_interceptor.OpenCensusClientInterceptor(
+            tracer, host_port=HOST_PORT)
+        channel = grpc.insecure_channel(HOST_PORT)
+        channel = grpc.intercept_channel(channel, tracer_interceptor)
+        stub = hello_world_pb2_grpc.GreeterStub(channel)
+        response = stub.SayHello(hello_world_pb2.HelloRequest(name='you'))
+        print("Message received: " + response.message)

...but I doubt you want to do that, and I don't think that matches the behavior of the clients in other languages.

Changing the tracer to use a new trace ID after closing the root span also fixes the problem, but may well break something else:

diff --git a/opencensus/trace/tracers/context_tracer.py b/opencensus/trace/tracers/context_tracer.py
index 1cb0306..b8e579c 100644
--- a/opencensus/trace/tracers/context_tracer.py
+++ b/opencensus/trace/tracers/context_tracer.py
@@ -17,6 +17,7 @@ import threading

 from opencensus.trace import execution_context
 from opencensus.trace.span_context import SpanContext
+from opencensus.trace.span_context import generate_trace_id
 from opencensus.trace import span as trace_span
 from opencensus.trace import span_data as span_data_module
 from opencensus.trace.exporters import print_exporter
@@ -116,6 +117,7 @@ class ContextTracer(base.Tracer):
             execution_context.set_current_span(cur_span.parent_span)
         else:
             execution_context.set_current_span(None)
+            self.span_context.trace_id = generate_trace_id()

         with self._spans_list_condition:
             if cur_span in self._spans_list:

And for a comparison, for about 15 minutes, I've been running the Java gRPC server https://github.com/orijtech/opencensus-for-grpc-java-developers receiving about 14 concurrent requests from the Python client with no problem at all

@odeke-em this is surprising since it looks like the problem is on the client side. Running the java grpc server with the python client, I'd still expect all requests to have the same trace ID since we're setting it in the client and passing it along to the server in the context. What am I missing here?

the issue I'm experiencing is related to using the tornado web framework in conjunction with the opencensus interceptor

@tab1293 I'd be amazed if tornado didn't cause serious problems for opencensus since we're storing the current span in a threadlocal and (as I understand it) tornado uses a single-threaded event loop.

For example, I'd expect this to report f2_span as a child of f1_span in tornado:

@gen.coroutine
def f1():
    tracer = Tracer()
    tracer.start_span('f1_span')
    try:
        r1 = yield expensive1()
        raise gen.Return(r1)
    finally:
        tracer.end_span()

@gen.coroutine
def f2():
    tracer = Tracer()
    tracer.start_span('f2_span')
    try:
        r2 = yield expensive2()
        raise gen.Return(r2)
    finally:
        tracer.end_span()

@gen.coroutine
def main():
    yield f1()
    yield f2()

instead of reporting them as siblings, as would be the case if f1 and f2 were run in separate threads.

I haven't tried running this, so take it with a grain of salt.

@c24t

...but I doubt you want to do that, and I don't think that matches the behavior of the clients in other languages.

I don't think it makes any sense to do that, it would require creating a new GRPC channel for each trace. Channels are expensive to create and should be used across stubs as per grpc/grpc-java#3268 (comment). I don't understand the current design of having to create a new interceptor for each trace, is this just a flawed paradigm specific to the OpenCensusClientInterceptor and Stackdriver exporter?

Changing the tracer to use a new trace ID after closing the root span also fixes the problem, but may well break something else

That looks like a valid fix to me. Are there any cases when there can be multiple root spans in a single trace? What specifically are you worried about breaking?

I'd be amazed if tornado didn't cause serious problems for opencensus since we're storing the current span in a threadlocal and (as I understand it) tornado uses a single-threaded event loop

Why is the local thread being used to store instances of spans and tracers? I'm confused to why the execution_context.py functionality is necessary.

instead of reporting them as siblings, as would be the case if f1 and f2 were run in separate threads

Where in the code would f1 and f2 be run in threads?

I don't understand the current design of having to create a new interceptor for each trace

I think this is just a bug, and that we should get a new trace ID or whole new span context on each call. This isn't specific to stackdriver, or even the grpc client interceptor.

Are there any cases when there can be multiple root spans in a single trace? What specifically are you worried about breaking?

Not as far as I know. I think this is the right fix too, I just need to verify it.

I'm confused to why the execution_context.py functionality is necessary.

It's so you can start a span in one place and end it in another without passing the span or tracer around. It's not necessary if you're only using the grpc interceptors, but if you create a span in application code we need to attach it as a child of the span created by the interceptor. In that case we get the current span from the execution context.

Where in the code would f1 and f2 be run in threads?

I mean if you were using threading instead of tornado's event loop.

@c24t I tried your change #505 and it did not fix this problem for me. I came up with a change that does fix it for me: #539

I think I may be missing some context though, I'm very open to hearing why this is a bad idea. 😅

I can trivially reproduce this bug with

import requests
import time
import random

from opencensus.ext.ocagent import (
    stats_exporter,
    trace_exporter,
)
from opencensus.trace import config_integration
from opencensus.trace.samplers import AlwaysOnSampler
from opencensus.trace.status import Status
from opencensus.trace.tracer import Tracer

def main():
  config_integration.trace_integrations(['requests'])
  tracer = register_all('mediasearch-py')

  while True:
    query = input('Content to search$ ')
    if query == '' or query == '\n':
        return
    print('query: "' + query + '"')

    with tracer.span(name='SearchMedia') as span:
        doSearch(tracer, query)
        # span.finish()

    # time.sleep(random.random() * 37)

def register_all(service_name):
    texp = trace_exporter.TraceExporter(
            service_name=service_name,
            endpoint='localhost:55678')

    return Tracer(exporter=texp, sampler=AlwaysOnSampler())

def doSearch(tracer, query):
    with tracer.span(name='doSearch') as span:
        res = requests.post('http://localhost:9778/search', json={'keywords': query})
        pages = res.json()
        if not pages:
            return

        for page in pages:
            items = page['items']
            for i, item in enumerate(items):
                id = item['id']
                if 'videoId' in id:
                    print('URL: https://youtu.be/{videoId}'.format(**item['id']))
                elif 'channelId' in id:
                    print('ChannelURL: https://www.youtube.com/channel/{channelId}'.format(**item['id']))

                snippet = item['snippet']
                snippet.setdefault('description', 'Unknown')
                print('Title: {title}\nDescription: {description}\n\n'.format(**snippet))

if __name__ == '__main__':
  main()

and even single trace shares the same TraceID, using the latest version of OpenCensus-Python aka v0.7.7 and ocagent version 0.0.1.

Please re-open this bug.