Cujojs/REST - Spans not being sent to zipkin about zipkin-js

[codefromthecrypt]

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

On Wed, Aug 17, 2016 at 5:47 PM, Janusz Piechówka [email protected]
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]

@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]

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 [email protected]
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]

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]

@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]

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 [email protected]
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]

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 [email protected]
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 <
[email protected]> 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]

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

[ocastx]

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]

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]

@ocastx Your solution works, this helped

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

[ocastx]

@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]

@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]

@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]

@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]

Closing it due to inactivity and #375