set_tag is not updating tags and duration

[dhineshmm]

New to opentracing, Try to explore opentracing and jaeger UI. After gone through the lessons, With help of lesson01 solution https://github.com/yurishkuro/opentracing-tutorial/tree/master/python/lesson01/solution tried to include some logic with sleep to add some tags.

Recently added tags are not listed in jaeger UI. When i use span.finish(), Recently added tags and duration works fine. But it shows two span with same name.

Sample program:-
    child_span = create_child_span( exec_name );
    with span_in_context(child_span):
        child_span.set_tag('testing',get_current_time());
        time.sleep(10)
        ##os.system('echo In-progress '+exec_name+' ');
        time.sleep(10)
        child_span.set_tag('end_time',get_current_time());
        ## by commenting finish, recently added tags are not listing with proper duration of span
        ## by uncommenting, It shows one more same tag with recently added tags and duration
        #child_span.finish(); ## by commenting end_time or any tag is not listing as well as duration of span
        return child_span

[yurishkuro]

are you using Python 3?

[dhineshmm]

Using python 2.7.5

## Log
Initializing Jaeger Tracer with UDP reporter
Using sampler ConstSampler(True)
opentracing.tracer initialized to <jaeger_client.tracer.Tracer object at 0x1c26750>[app_name=master-app]
create_child_wo_function
Reporting span ed0bc31d55b5f1a5:8bd95e874ec147dc:ed0bc31d55b5f1a5:1 master-app.command-exec-01
create_child_with_function
Reporting span ed0bc31d55b5f1a5:d476f2975c4ac445:ed0bc31d55b5f1a5:1 master-app.command-exec-02
Reporting span ed0bc31d55b5f1a5:d476f2975c4ac445:ed0bc31d55b5f1a5:1 master-app.command-exec-02
Reporting span ed0bc31d55b5f1a5:ed0bc31d55b5f1a5:0:1 master-app.master-app

## Only one span created for root, with sleep
    with tracer.start_span(span_name) as root_span:
         with span_in_context(root_span):
              root_span.set_tag('start_time', get_current_time() );
              root_span.set_tag('test', 'data' );
              time.sleep(30)
              root_span.set_tag('span', span_name)
              root_span.info('Root span created...');
              create_child_wo_function('command-exec-01',3);
              create_child_with_function('command-exec-02',3);

## Only one span created for child-01, with sleep
def create_child_wo_function(exec_name, count):
    print "create_child_wo_function";
    global tracer, span
    span_name = exec_name
    parent_span = get_current_span()
    parent_span.info('Will trigger '+span_name+' span...');
    with tracer.start_span(span_name, child_of=parent_span.context) as child_span:
         with span_in_context(child_span):
              child_span.set_tag('span', span_name)
              child_span.set_tag('start_time', get_current_time() );
              time.sleep(30)
              child_span.set_tag('test', 'data' );
              child_span.set_tag('end_time',get_current_time());
              #child_span.finish();
              return child_span
## two spans created with function call
def create_child_span(span_name):
    global tracer, span
    parent_span = get_current_span()
    parent_span.info('Will trigger '+span_name+' span...');
    with tracer.start_span( span_name, child_of=parent_span.context) as child_span:
        with span_in_context(child_span):
            child_span.set_tag('span', span_name)
            child_span.set_tag('start-time', get_current_time());
            child_span.info('Child span created...');
            return child_span
    return None

def create_child_with_function(exec_name, count):
    print "create_child_with_function";
    created_child_span = create_child_span( exec_name );
    with created_child_span as child_span:
        with span_in_context(child_span):
            child_span.set_tag('testing',get_current_time());
            time.sleep(20)
            ##os.system('echo In-progress '+exec_name+' ');
            time.sleep(10)
            child_span.set_tag('end_time',get_current_time());
            #child_span.finish();
            return child_span

[dhineshmm]

Finally arrived it to have single span, by start a span through function call and sleep

def create_child_span(span_name):
    global tracer, span
    parent_span = get_current_span()
    parent_span.info('Will trigger '+span_name+' span...');
    child_span = tracer.start_span( span_name, child_of=parent_span.context)
    with span_in_context(child_span):
        child_span.set_tag('span', span_name)
        child_span.set_tag('start-time', get_current_time());
        child_span.info('Child span created...');
        return child_span
    return None

def create_child_with_function(exec_name, count):
    print "create_child_with_function";
    child_span = create_child_span( exec_name );
    with span_in_context(child_span):
        child_span.set_tag('testing',get_current_time());
        time.sleep(20)
        ##os.system('echo In-progress '+exec_name+' ');
        time.sleep(10)
        child_span.set_tag('end_time',get_current_time());
        child_span.finish();
        return child_span

[yurishkuro]

tip: enclose code snippets between lines containing 3 back ticks (see syntax hilighting)

[yurishkuro]

Why do you have return child_span everywhere? Every time it's local to the function and is finished there. It seems you're getting double spans simply because you're calling finish twice on them.

[dhineshmm]

Yes not required to return from create_child_with_function and create_child_wo_function subroutine. By returning span from create_child_span function #1 and use the same span in create_child_with_function caller function to update all the tags and logs to collector.

finish required to close, in case span was created in some other function and used here.

no need to return child_span and call finish at create_child_wo_function function. Since span created and updated all information with this same block

[yurishkuro]

please post the compete program

[dhineshmm]

import time
import opentracing
from lib.tracing import init_tracer
from opentracing_instrumentation.request_context import get_current_span, span_in_context
from opentracing.ext import tags
from opentracing.propagation import Format
import os
import json
from datetime import datetime

#global tracer

def get_current_time():
    get_current_time = datetime.utcnow().strftime('%Y-%m-%d %H:%M:%S.%f')[:-3]
    return get_current_time;

def create_span_obj(span_name,parent_span=None):
    span = None
    if parent_span:
        span = tracer.start_span( span_name, child_of=parent_span.context)
    else:
        span = tracer.start_span( span_name)
    with span_in_context(span):
        span.set_tag('span', span_name)
        span.set_tag('start-time', get_current_time());
    return span

def create_and_update(span_name, parent_span):
    with tracer.start_span(span_name, child_of=parent_span.context) as child_span:
         with span_in_context(child_span):
              child_span.set_tag('span', span_name)
              child_span.set_tag('start_time', get_current_time() );
              time.sleep(2)
              child_span.set_tag('test', 'data' );
              child_span.set_tag('end_time',get_current_time());
              #child_span.finish();
def update_details( span, data ):
    with span_in_context(span):
        span.set_tag('data',data);
        time.sleep(2)
        span.set_tag('end-time', get_current_time());
        span.finish()

process_name = 'master-app'
tracer = init_tracer(process_name)
root_span = create_span_obj(process_name);
print root_span
child_span = create_span_obj('child_span', parent_span=root_span);
update_details( child_span, 'child span' );
create_and_update( 'create_and_update_child', root_span);
update_details( root_span, 'root_span' );

# yield to IOLoop to flush the spans
time.sleep(5)
tracer.close()