Cujojs/REST - Spans not being sent to zipkin #32

jpiechowka · 2016-08-17T09:47:59Z

I am making proof of concept client - server app with tracing via zipkin. The problem is spans are not being sent to Zipkin running on localhost when im using Cujojs/REST instrumentation. I can make request to my server (running on http://localhost:9999) and I can properly read Zipkin headers on the server. This is my Js client code:

const {Tracer, BatchRecorder, ExplicitContext} = require('zipkin');
const {HttpLogger} = require('zipkin-transport-http');
const {restInterceptor} = require('zipkin-instrumentation-cujojs-rest');

const rest = require('rest');

const ctxImpl = new ExplicitContext();
const recorder = new BatchRecorder({
    logger: new HttpLogger({
        endpoint: 'http://localhost:9411/api/v1/spans'
    })
});

const tracer = new Tracer({ctxImpl, recorder});
const nameOfRemoteService = 'Client';
const client = rest.wrap(restInterceptor, {tracer, serviceName: nameOfRemoteService});

client({
    method: 'GET',
    path: 'http://localhost:9999/request'
}).then(function(response) {
    console.log('response: ', response);
});

The text was updated successfully, but these errors were encountered:

codefromthecrypt · 2016-08-17T10:04:14Z

Can you change to ConsoleRecorder and paste the results of that?

On Wed, Aug 17, 2016 at 5:47 PM, Janusz Piechówka notifications@github.com
wrote:

I am making proof of concept client - server app with tracing via zipkin.
The problem is spans are not being sent to Zipkin running on localhost when
im using Cujojs/REST instrumentation. I can make request to my server
(running on http://localhost:9999) and I can properly read Zipkin headers
on the server. This is my Js client code:

const {Tracer, BatchRecorder, ExplicitContext} = require('zipkin');
const {HttpLogger} = require('zipkin-transport-http');
const {restInterceptor} = require('zipkin-instrumentation-cujojs-rest');

const rest = require('rest');

const ctxImpl = new ExplicitContext();
const recorder = new BatchRecorder({
logger: new HttpLogger({
endpoint: 'http://localhost:9411/api/v1/spans'
})
});

const tracer = new Tracer({ctxImpl, recorder});
const nameOfRemoteService = 'Client';
const client = rest.wrap(restInterceptor, {tracer, serviceName: nameOfRemoteService});

client({
method: 'GET',
path: 'http://localhost:9999/request'
}).then(function(response) {
console.log('response: ', response);
});

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
#32, or mute the thread
https://github.com/notifications/unsubscribe-auth/AAD617wPCLYYGeBCgf-ED0A7MrPm0WfVks5qgtjPgaJpZM4JmRmJ
.

jpiechowka · 2016-08-17T10:08:19Z

@adriancole Sure!
This is the output:

Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): ServiceName("Client")
Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): Rpc("GET")
Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): BinaryAnnotation(http.url="http://localhost:9999/request")
Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): ClientSend()
Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): BinaryAnnotation(http.status_code="200")
Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): ClientRecv()

codefromthecrypt · 2016-08-17T10:14:17Z

ok well that looks fine.. is there any error in the zipkin-server log or
dropped things on http://localhost:9411/metrics ?

On Wed, Aug 17, 2016 at 6:08 PM, Janusz Piechówka notifications@github.com
wrote:

@adriancole https://github.com/adriancole Sure!
This is the output:

Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): ServiceName("Client")
Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): Rpc("GET")
Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): BinaryAnnotation(http.url="http://localhost:9999/request")
Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): ClientSend()
Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): BinaryAnnotation(http.status_code="200")
Record at (spanId=877b1886598fb9dd, parentId=877b1886598fb9dd, traceId=877b1886598fb9dd): ClientRecv()

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#32 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAD615DSGmXl23VtWHKXiG9w34Rkz-Hzks5qgt2UgaJpZM4JmRmJ
.

jpiechowka · 2016-08-17T10:53:09Z

There were no errors on the console.
I restarted Zipkin, this is what is in metrics before request:

    "mem":66982,
    "mem.free":8272,
    "processors":4,
    "instance.uptime":1776620,
    "uptime":1782678,
    "systemload.average":-1.0,
    "heap.committed":43820,
    "heap.init":16384,
    "heap.used":35547,
    "heap":253440,
    "nonheap.committed":23680,
    "nonheap.init":160,
    "nonheap.used":23163,
    "nonheap":0,
    "threads.peak":23,
    "threads.daemon":11,
    "threads.totalStarted":26,
    "threads":22,
    "classes":7409,
    "classes.loaded":7414,
    "classes.unloaded":5,
    "gc.copy.count":311,
    "gc.copy.time":580,
    "gc.marksweepcompact.count":2,
    "gc.marksweepcompact.time":65,
    "httpsessions.max":-1,
    "httpsessions.active":0

This is what is after I made a request:

    "mem":67094,
    "mem.free":11387,
    "processors":4,
    "instance.uptime":1848323,
    "uptime":1854374,
    "systemload.average":-1.0,
    "heap.committed":43820,
    "heap.init":16384,
    "heap.used":32432,
    "heap":253440,
    "nonheap.committed":23936,
    "nonheap.init":160,
    "nonheap.used":23274,
    "nonheap":0,
    "threads.peak":26,
    "threads.daemon":15,
    "threads.totalStarted":30,
    "threads":26,
    "classes":7493,
    "classes.loaded":7498,
    "classes.unloaded":5,
    "gc.copy.count":313,
    "gc.copy.time":587,
    "gc.marksweepcompact.count":2,
    "gc.marksweepcompact.time":65,
    "counter.status.200.metrics":2,
    "gauge.response.metrics":3.0,
    "httpsessions.max":-1,
    "httpsessions.active":0

jpiechowka · 2016-08-17T12:42:30Z

@adriancole This is the server code I wrote in Spark Java very fast without proper error handling, hardcoded spanId for now:

public class SparkServer {

    public static void main (String[] args){
        port(9999);

        Brave brave = new Brave.Builder("SparkServer")
                .spanCollector(HttpSpanCollector.create("http://localhost:9411/", new EmptySpanCollectorMetricsHandler()))
                .build();

        get("/request", (request, response) -> {
            final String debugSpanID = "1234abcd1234abcd";

            final long traceID = new BigInteger(request.headers("X-B3-Traceid"), 16).longValue();
            final long spanID = new BigInteger(debugSpanID, 16).longValue();
            final long parentID = new BigInteger(request.headers("X-B3-Traceid"), 16).longValue();

            brave.serverTracer().setStateCurrentTrace(traceID, spanID, parentID, "ServerSpan");
            brave.serverTracer().setServerReceived();

            Random rand = new Random();
            final int sleep = rand.nextInt(2001) + 500;
            Thread.sleep(sleep);

            brave.serverTracer().setServerSend();
            brave.serverTracer().clearCurrentSpan();
            return "Hello world";
        });

        exception(InterruptedException.class, (exception, request, response) -> {
            System.out.println("\n\n INTERRUPTED EXCEPTION\n PRINTING STACK TRACE \n\n");
            exception.printStackTrace();
        });
    }
}

Right now only server span is sent to zipkin, and I can see it in the UI.

codefromthecrypt · 2016-08-17T13:11:59Z

stuck on something else at the moment. can you verify that if you run my
demo you can see the spans in zipkin? maybe you can hack it for cujo..

If you can't see spans in zipkin running my branch as-is, maybe it is
something about your node setup?

openzipkin/zipkin-js-example#1

On Wed, Aug 17, 2016 at 6:53 PM, Janusz Piechówka notifications@github.com
wrote:

There were no errors on the console.
I restarted Zipkin, this is what is in metrics before request:

"mem":66982,
"mem.free":8272,
"processors":4,
"instance.uptime":1776620,
"uptime":1782678,
"systemload.average":-1.0,
"heap.committed":43820,
"heap.init":16384,
"heap.used":35547,
"heap":253440,
"nonheap.committed":23680,
"nonheap.init":160,
"nonheap.used":23163,
"nonheap":0,
"threads.peak":23,
"threads.daemon":11,
"threads.totalStarted":26,
"threads":22,
"classes":7409,
"classes.loaded":7414,
"classes.unloaded":5,
"gc.copy.count":311,
"gc.copy.time":580,
"gc.marksweepcompact.count":2,
"gc.marksweepcompact.time":65,
"httpsessions.max":-1,
"httpsessions.active":0

This is what is after I made a request:

"mem":67094,
"mem.free":11387,
"processors":4,
"instance.uptime":1848323,
"uptime":1854374,
"systemload.average":-1.0,
"heap.committed":43820,
"heap.init":16384,
"heap.used":32432,
"heap":253440,
"nonheap.committed":23936,
"nonheap.init":160,
"nonheap.used":23274,
"nonheap":0,
"threads.peak":26,
"threads.daemon":15,
"threads.totalStarted":30,
"threads":26,
"classes":7493,
"classes.loaded":7498,
"classes.unloaded":5,
"gc.copy.count":313,
"gc.copy.time":587,
"gc.marksweepcompact.count":2,
"gc.marksweepcompact.time":65,
"counter.status.200.metrics":2,
"gauge.response.metrics":3.0,
"httpsessions.max":-1,
"httpsessions.active":0

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#32 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAD61wn_jlN0fbGKPIVXJu3Tlz5BYzatks5qgugVgaJpZM4JmRmJ
.

codefromthecrypt · 2016-08-17T13:19:57Z

basically if you can get an example project (not just a snippet), ex in a
temporary repo, it would cut down the time it would take for me to help. At
this point, it sounds like propagation isn't a problem.

If you can make a quick node server that calls youtube or something, I
don't mind taking a look at that and trying to figure out why. What you
pasted doesn't look like there's something obvious, so a little project
might get us closer to a solution.

On Wed, Aug 17, 2016 at 9:11 PM, Adrian Cole adrian.f.cole@gmail.com
wrote:

stuck on something else at the moment. can you verify that if you run my
demo you can see the spans in zipkin? maybe you can hack it for cujo..

If you can't see spans in zipkin running my branch as-is, maybe it is
something about your node setup?

openzipkin/zipkin-js-example#1

On Wed, Aug 17, 2016 at 6:53 PM, Janusz Piechówka <
notifications@github.com> wrote:
There were no errors on the console.
I restarted Zipkin, this is what is in metrics before request:
"mem":66982,
"mem.free":8272,
"processors":4,
"instance.uptime":1776620,
"uptime":1782678,
"systemload.average":-1.0,
"heap.committed":43820,
"heap.init":16384,
"heap.used":35547,
"heap":253440,
"nonheap.committed":23680,
"nonheap.init":160,
"nonheap.used":23163,
"nonheap":0,
"threads.peak":23,
"threads.daemon":11,
"threads.totalStarted":26,
"threads":22,
"classes":7409,
"classes.loaded":7414,
"classes.unloaded":5,
"gc.copy.count":311,
"gc.copy.time":580,
"gc.marksweepcompact.count":2,
"gc.marksweepcompact.time":65,
"httpsessions.max":-1,
"httpsessions.active":0
This is what is after I made a request:
"mem":67094,
"mem.free":11387,
"processors":4,
"instance.uptime":1848323,
"uptime":1854374,
"systemload.average":-1.0,
"heap.committed":43820,
"heap.init":16384,
"heap.used":32432,
"heap":253440,
"nonheap.committed":23936,
"nonheap.init":160,
"nonheap.used":23274,
"nonheap":0,
"threads.peak":26,
"threads.daemon":15,
"threads.totalStarted":30,
"threads":26,
"classes":7493,
"classes.loaded":7498,
"classes.unloaded":5,
"gc.copy.count":313,
"gc.copy.time":587,
"gc.marksweepcompact.count":2,
"gc.marksweepcompact.time":65,
"counter.status.200.metrics":2,
"gauge.response.metrics":3.0,
"httpsessions.max":-1,
"httpsessions.active":0
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#32 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAD61wn_jlN0fbGKPIVXJu3Tlz5BYzatks5qgugVgaJpZM4JmRmJ
.

jpiechowka · 2016-08-17T14:01:49Z

Thanks, I will create an example project when I am at home in a couple of hours.

ocastx · 2016-08-17T16:46:11Z

Had the same problem today with HttpLogger. What I found was that my process terminated before the Logger could send the requests to zipkin.

Just to check if this is there problem here too, you can quickly add a timeout like this to your code to let the process wait 5 seconds before exiting so the requests can be send:

setTimeout(function () {
  console.log('timeout');
}, 5000);

I've already created a ticket to check why this is done in the Logger. You can check the status here: #33

jquatier · 2016-08-17T17:25:34Z

I do think this is the same issue as #33. I'm currently using this recorder with Restify, which keeps the server up anyway so it can handle requests, so I haven't run into this yet.

jpiechowka · 2016-08-17T19:08:48Z

@ocastx Your solution works, this helped

setTimeout(function () {
  console.log('timeout');
}, 5000);

ocastx · 2016-08-17T19:28:17Z

@jpiechowka Be sure to follow #33 because the 5 sec. should not be a permanent fix for the problem.
I've also created a fork/pull request with the fix, so if you need it (without the 5 sec. timeout) you can use this until this is merged: https://github.com/ocastx/zipkin-js

jpiechowka · 2016-08-17T19:41:25Z

@ocastx I have subscribed already. Make sure to format your links correctly, so they don't point to 404 page like right now :D

pavolloffay · 2016-10-14T09:54:39Z

@adriancole this https://github.com/hawkular/hawkular-apm/blob/master/examples/polyglot-zipkin/js-express/app.js#L93 can be used as a reproducer.

jcchavezs · 2019-07-27T09:23:27Z

@jpiechowka I know this issue is old based on what I read and my own experience, this could have been fixed with last fixes from @adriancole (check version 0.18.6). Would you be able to try again with that version?

jcchavezs · 2019-11-27T12:01:28Z

Closing it due to inactivity and #375

pavolloffay mentioned this issue Oct 13, 2016

HWKAPM-689 | reproducer for missing client spans from nodejs app hawkular/hawkular-apm#635

Merged

jcchavezs closed this as completed Nov 27, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Cujojs/REST - Spans not being sent to zipkin #32

Cujojs/REST - Spans not being sent to zipkin #32

jpiechowka commented Aug 17, 2016

codefromthecrypt commented Aug 17, 2016

jpiechowka commented Aug 17, 2016

codefromthecrypt commented Aug 17, 2016

jpiechowka commented Aug 17, 2016

jpiechowka commented Aug 17, 2016

codefromthecrypt commented Aug 17, 2016

codefromthecrypt commented Aug 17, 2016

jpiechowka commented Aug 17, 2016

ocastx commented Aug 17, 2016 •

edited

Loading

jquatier commented Aug 17, 2016

jpiechowka commented Aug 17, 2016

ocastx commented Aug 17, 2016 •

edited

Loading

jpiechowka commented Aug 17, 2016 •

edited

Loading

pavolloffay commented Oct 14, 2016

jcchavezs commented Jul 27, 2019

jcchavezs commented Nov 27, 2019

Cujojs/REST - Spans not being sent to zipkin #32

Cujojs/REST - Spans not being sent to zipkin #32

Comments

jpiechowka commented Aug 17, 2016

codefromthecrypt commented Aug 17, 2016

jpiechowka commented Aug 17, 2016

codefromthecrypt commented Aug 17, 2016

jpiechowka commented Aug 17, 2016

jpiechowka commented Aug 17, 2016

codefromthecrypt commented Aug 17, 2016

codefromthecrypt commented Aug 17, 2016

jpiechowka commented Aug 17, 2016

ocastx commented Aug 17, 2016 • edited Loading

jquatier commented Aug 17, 2016

jpiechowka commented Aug 17, 2016

ocastx commented Aug 17, 2016 • edited Loading

jpiechowka commented Aug 17, 2016 • edited Loading

pavolloffay commented Oct 14, 2016

jcchavezs commented Jul 27, 2019

jcchavezs commented Nov 27, 2019

ocastx commented Aug 17, 2016 •

edited

Loading

ocastx commented Aug 17, 2016 •

edited

Loading

jpiechowka commented Aug 17, 2016 •

edited

Loading