Hacker News Reader

Comment by rdli | Hacker News Reader

I'm surprised the article didn't mention anything about the nuances of actual logging in a distributed architecture. In particular, when a request starts to span multiple containers or microservices, you need a way to correlate all log data to a given request. You typically do this by propagating a trace ID through your logging system, and a vector clock-type thing for causal ordering. If you can't tell which log statements belong to which request and the order in which they occur, debugging is quite hard :-).

View on HN

There are a number of distributed tracing tools now. I've heard good things about Zipkin[0], but not used it myself.

The key is not just to have a single request ID, but also to provide hop IDs. Relying on clocks, even vector clocks, isn't ideal in a share-nothing architecture.

[0] http://zipkin.io/

Zipkin is great. It's pretty simple to set up, and you can instrument pretty much anything to send data to it. We made it a part of our internal httpclient and Kafka client so most teams get the tracing for free. You can even visualize the internals of Cassandra with zipkin. :)

There's support for a Spark-job that generates a visual map of all your services' dependencies[0] where the strength of their relationship is represented by the thickness of the lines.

[0]: http://thelastpickle.com/images/using-zipkin-graph.png

I've just started down a path for us and been pretty happy with Loggly so far.

Just by adding a UUID to the requests as they're initially received I'm able to follow the chain of events across 5 different services, a message queue, and reconcile with any code exception reports from Bugsnag.

We don't have a lot of unique clients, but we do have a lot of requests.

Loggly can be set to parse logs (or have the data sent directly to it) and then tag messages with keys/values that can let you watch your request through every server.

Now that I understand the parent comment, I don't think this quite solves the problem he's asking unless all of your services are perfectly synchronized. No?

For us, messaging between services go through queues and a client request might start in a particular service and wind it's way through a few others to finish the work. You wouldn't have the same client requesting things from two different services simultaneously, though in fairly short order they come through. Our use case might be just simple enough that this wouldn't work for a lot of people.

Also, if I'm looking at access logs I'm not going to have that ID unless I start putting it in request headers. Right now the application logs and other monitoring tools pick it up though.

Edit: Didn't see mention of the clock on my first post, but it still stands for us that we're not in the millisecond timings between requests going in and out of services so we haven't had a problem with the timestamps from the systems they're on. Requests generally take a few seconds to process (handle a file upload of decent size, ETL some data, pump out some output document, etc) so each step through a service buys enough time before moving on to the next thing that we're not getting out of order log statements across each service.

> Edit: Didn't see mention of the clock on my first post, but it still stands for us that we're not in the millisecond timings

Vector clocks don't necessarily have much to do with clocks. It's an algorithm for generating order in a distributed system.

https://en.wikipedia.org/wiki/Vector_clock

Yeah, Loggly is very solid. I've set up logging infrastructure for 2 companies using it now. Their structured logging parsing, searching, and alerting is fantastic.

Any tips for a beginner on optimizing usage of the dashboard? Not using it for much right now, and I feel like the interface is going to take awhile to optimize/learn.

How are you passing that UUID along the request chain? For instance, when one microservice calls another, does it have to be manually passed in?

Some platforms will do this for you -- Cloud Foundry will show `x-cf-requestid` for anything that passed through the gorouter and back.

My web stack checks for a specific header at each potential level of entry, and in the absence of a value, generates one. Then each layer's logger will log it back out. It's pretty straightforward for web requests - just use the plumbing that's already there, headers.

While the article does not touch on this explicitly, Docker's Log Driver for Fluentd supports tags, which can be used to pass on container name/ID and other metadata to wherever logs are sent. Since Docker Machine itself allows these metadata to be passed on via API ({{.Name}}, etc.) one can create a fairly robust system to track log lineage.

That approach requires a lot of post processing to make it useful. Further it's pretty hard (near impossible) to do causal ordering.

I agree on the near-impossibility of causal ordering at scale. I don't see the need for a lot of "post processing". Adding filters in Fluentd is fairly simple: http://docs.fluentd.org/articles/filter-plugin-overview

How would passing on the container ID help in mapping multiple log messages to the same request? If a request is going through multiple containers, you'll get multiple container IDs.

To solve this problem, you need a unique trace ID and vector clock, and this actually needs to propagated through your logging system, not through container tags.

Ah, I completely misunderstood. Yes, you are right: Threading data together across multiple containers belonging to a single logical request is hard (and AFAIK, none of the container orchestration tools deal with it well).

How is the unique trace ID implemented? Vector clocks would be in use by your distributed data store for conflict resolution such as Riak does. Could you elaborate on how you've implemented such a system?

It's not about conflict resolution, it's about ordering.

Imagine you have 3 services. A calls B calls C. A request goes into A. The request fails. Since there are 3 services involved, you want to be able to see the log statements of all 3 services, in order. To do this, you need a UUID that is passed from A to B to C and a vector clock that is incremented from A to B to C so you get perfect ordering. Passing the data around is not super hard (you can use HTTP headers, for example). The tricky bit is having a library that does the right thing in A and B and C. And if A is written in Java and B is written in NodeJS, that library better work on both!

Yes, this makes total sense. I think I completely misunderstood you post earlier. Thanks for the clarification.

Can you elaborate on the use case you are referring to where a single request spans multiple containers? Are you referring to a "fan-out"?

Really, it's when you're doing microservices, and each service is deployed to a different container. Typically your business logic is now spread across multiple containers. For example, you might have a recommendation service that looks up location in the geo service. If the geo service returns bad data, then the exception is thrown in the recommendation service. But to debug this properly, you really want to see the logging in both the geo service and the recommendation service, in order. As your topologies get deeper, the problem gets exponentially harder.

This is false. You can also do this without microservices or containers. Or also syslog. Just my two cents!

I wasn't saying you needed microservices or containers to do distributed logging. My point is that if you're building a distributed system, you need distributed logging (tracing) semantics. The actual logging mechanism (syslog, fluentd, etc) can be used -- as long as you propagate your UUID, etc.

Reply on news.ycombinator.com