Tracing and Monitoring Microservices and Applications with Spring Sleuth (Ep. 29)

Episode 17 · 22:24 · SRT · archive.org · all Tanzu Talk

0:00

Well, here we are at SpringOne Platform, the most awesome named conference of the year. Don't you agree? Of course. And I have a guest with myself. You want to introduce yourself? Yeah. Hi, everybody. My name is Marcin Grzejszczak. I'm sorry for my surname, which is impossible to pronounce by foreigners. I'm working for the Spring Cloud team on basically mostly Sleuth, which is our implementation of distributed tracing with Spring Cloud and Spring Boot. And the other project is Spring Cloud Contract, but we're going to focus on the first one, I guess. Oh, yeah. I forgot about that one, too. We were walking between, I don't know, some meetup talk or something in a bar in a park, and you were telling me all about that last one. Now I remember. Yeah. Yeah, a bar in a park. Very nice. I mean, that's typical stuff that you do in a bar in a park and talk about Spring Cloud. Exactly. So how long have you been working on this Sleuth stuff? Actually, I joined Pivotal in December. So since December. Yeah, yeah, yeah. And what made you interested in it? Actually, I started in my previous company. We started, I didn't even know that it's called distributed tracing back then, but we have implemented in our open source solution that was related to microservices based on Groovy. We created correlation ID passing. So we did log correlation by ourselves, and I've contributed all of that to Spring Cloud. All right. So you got in through code. Yes. So before even joining Pivotal, I've already contributed some stuff to Spring Cloud Sleuth. And so let's start talking about Sleuth and Zipkin underneath it by saying the problem you were trying to solve. So what was the issue that you had that brought you to doing this? And are there things that you tried that you decided not to go with instead? Or like what brought you to it all?

2:00

So basically, we had a problem that, I mean, we had a distributed system. We've invested a lot of time to, let's say, provide some standards of logging and running applications. Some basic stuff that you do when you want to go in the microservice direction. And the problem was that when an exception was thrown somewhere in the system, we couldn't correlate that with any sort of, like, user who clicked around or with some sort of a situation that happened in the system. I mean, there was an exception thrown somewhere, and then we didn't know what happened before and what happened after. Oh, right. So it was like going into a dark room to try to find something. So what we wanted to have is, like, you know, some breadcrumbs that we could follow, right? It happened here, then something happened, and so on and so forth. At that time, our correlation ID, it was actually even, it was not, let's say, proper correlation ID in terms of Zipkin, but our correlation ID had a user ID attached. So when a user, like somebody from customer service was clicking around, he had an exception, he called us, we knew who he is or she, so we could correlate easily who clicked, then we knew when the exception happened. So then we could find the proper correlation ID, and we went to some, at that time, we had Elasticsearch.org slash Kibana stack, so we went to Kibana, and we could see all the, you know, historical requests before the exception and what happened after. So that way, in a distributed system where we had quite a few microservices, a couple of monoliths, we could find what happened. Right, so you have a user, like, clicking around doing something, it's always a bad word because it's overloaded, but they're doing some sort of transaction or some action that begins and ends. Yes. And spans a lot of different services, and so something will go wrong, and I guess, you know, you can look at the logs and, like, try to figure out, like, which logs are related to that user by time and machine they were on.

4:10

But then, as you're getting to, like, if you can somehow pass some unique ID through to every component of that, that gets you a little better as far as filtering the logs out to know that it's related to not only this user and not only this part in time, but this intention of them doing something, this transaction. Yeah, precisely, so in the distributed tracing nomenclature, this correlation ID I was talking about, and what you have just mentioned, it's called trace ID. So, yeah, for a single, let's say, business operation that can span throughout, you know, different microservices or monoliths, you have always the same value of that ID. Coming back to what you said, actually, one of the architects back in that company had an idea because I said that, I mean, right now we are blind. We cannot see what's happening in the system for a particular problem. So, he suggested that what we can do is to SSH to every machine and tail and grab the logs, right? So, tail the logs and grab for an error. So, of course, you can do that, but I don't think it's the best solution. I mean, even on Stack Overflow, out of curiosity, I checked if it's possible to batch SSH to machines to grab and tail. Oh, right, right, right. But, no, I mean, don't do that. It's pointless. So, we needed a solution. Well, you laugh, but when I used to work on systems management stuff, like, when would this have been? Over 10 years ago? Like, that was one thing we did. Like, if you wanted to, like, suck out logs, you could always SSH and tail from it. I mean, obviously, you can do that, and it will work. This is back in the early 2000s. But it's cumbersome. It's difficult, right? It takes a lot of energy and time. Yeah. And it's much better to shift it the other way around. So, what we did is that, because we had some, let's see, homemade solutions. We had some cloud somewhere without any abstraction, like Cloud Foundry.

6:13

So, we had to invest a lot of time to unify how all of the applications were logging. Because, of course, as it is in companies, it turns out at some point that every application does the same thing in a different way. So, if you want to just standardize stuff, you have to invest a lot of time. So, we had our applications put their logs in, like, always the same place. And we had a process with log slash forwarder. Right now, it's called FileBeat. So, this application was harvesting the logs and putting them all in one place, which was log stash. Right. Log stash parsed it into pieces and put it into the database. So, it's, like, exactly the same thing you can do right now with Cloud Foundry. Because, by default, all the logs are put, like, into such a place that the Logregator application can take it. Like, with Logregator, you have all the logs in one place. So, a lot of the job that we have done, like, manually to standardize, and we spend a lot of bucks on this. Because, like, it takes time. And time costs money. So, you in Cloud Foundry get out of the box for free. And then you can do whatever you want. For example, like, you know, cut it into pieces and present this. You can transform the logs or forward them on to something else. Whatever you want. Or just load them up in your plain text editor when you're lonely. Of course. It's what we always do, like, when we're lonely. We re-logs. So, yeah. So, that was the solution. And right now with Sluf, what you get is default logging pattern. Oh, by the way, I'm pretty sure often people, like, I mean, they're logging, that they're doing their logging, but often their pattern isn't proper. What does it mean? Often people forget, for example, to pass the thread name in the logs. Oh, right. So, when you're doing, let's say, some parallel processing or stuff, you're totally blind.

8:14

Because you don't even know which thread did that. Like, you have a log, then you have another one. And you don't know, was it sequential? Was it in parallel? You have no idea because you don't log the thread. Because you don't have the thread in there. Yeah, yeah. So, in Sluf, we provide a default logging pattern. So, we don't have to think about this. And, basically, if you have Sluf in every single application that you have, you have standardized the logging pattern because you have it out of the box. Then, if you're using Loggregator in Cloud Foundry, you standardize the way logs are aggregated. And, you know, it takes a lot of work to actually properly instrument the code to pass the tracing information, like, between threads, context, libraries. It was hectic work and still is because libraries change. There are some special use cases, so we have to invest a lot of time. So, it's better to use Sluf than manually try to do all of that yourself. Right. And, I mean, you're getting to what it seems like the, at least from my perspective of having worked on this stuff a long time ago, the core hard part is, there's two things at least. I'm sure there's more. But, one, there's instrumenting the code so it puts out the right ID, so it can get the ID. And propagate it. Yeah. And then, also, not only so it can get it, but so that it can use it. And so, like, that's, like, anytime you have to have developers do something, it's a world of hurt. Yes. I mean, that was the crucial thing. But getting a framework in place that works across many different services and even types of code. And that kind of gets to the second thing is there's a standard of how you think about and actually do this, right? Whether it's the log format or other things like that. But those two things together, then you can finally, like, that's always the problem, at least I would encounter with monitoring, is just instrumenting the stuff. Right? And then, as a systems management vendor, all the value that you bring is when the code isn't instrumented. And you make up for the lack of that. But, anyways, instrumenting the code is incredibly hard. Yes, it is.

10:14

And, obviously, we haven't done everything in the perfect way. For sure, there's going to be some issues. But we are quite stable. And there are not that many bugs, fortunately. And we try to really be immediate with fixing them. But, in general, it's pretty stable. So, I'm really happy with the quality of instrumentation that we have at the moment. Yeah, and we support quite a few things. And we give, let's say, easy, we provide an easy way how to, let's say, instrument new stuff that we don't instrument at the moment. So, there's at least two more things we should talk about before we wrap up this supposedly quick recording here. One of them is, so, we don't have a terminal here for you to demonstrate it. But, like, how does it work? Like, how, like, and I assume there's, like, some service registry thing that is a piece of code. You're, like, hey, give me the ID of the thing I'm participating in. And then you're, kind of, like, and it would be a good idea if I logged with this idea and stuff. And then, second, like, how, like, between not only different processes, but different types of languages and services and stuff, how does that work? Okay, so. Like, so how does it work? How does it work? So, in fact, if you're not creating anything custom, like, for example, you don't create a custom span. So, like, a local span, in fact. So, a span is an operation. For example, an RPC call is a span. So, it's a bounded operation that has its start and finish. It has a duration. So, if you don't create a manual one, you don't have to do anything. Right. It just happens out of the box. It's passed on between threads. It's added to headers in the requests. And then, basically, because we can wrap, or when you're running in an environment like this, you can wrap the HTTP calls, and then you could kind of wrap all the calls down into the system if there's some kind of runtime that supports it.

12:19

And do the old thing of, like, begin and end, begin and end. Precisely. So, since we are Zipkin compatible, you can have, for example, the Spring Cloud projects, like your Spring Cloud app. And you can send a request to, let's say, a Go app, which is Zipkin compatible, and it's going to work. Because the Go app is going to take the request. The headers are Zipkin compatible, so it knows what it's supposed to do. And let's say the Go app is sending the request to the Java app again, the Spring Boot app again. So, we take it over. And since we're Zipkin compatible, everything works fine. So, this is, let's say, the answer to your second question. And does that work across, like, event queues and things like that, or is it only HTTP? We do support Spring integration, so we do pass the headers and messages. Oh, okay, okay. So, we do support, for example, if you're using RabbitMQ or something like that, the headers are going to be appended to messages. And then, if you're Zipkin compatible on the other side, you can take the headers from the message on the other side and go. So, I guess, to try to painfully generalize it, whatever kind of, I don't know, process context you're operating in, you have a span in. Whether it's over HTTP or a message bus or whatever else we might think of, there's sort of like a bag of metadata associated with it. And part of what Sleuth and Zipkin does is, like, inserts a thing into that bag. And extracts it. Yeah, and then any process in there, I assume there's another sort of, like, standardized, if not sort of libraries that help you with this, is like, anytime you have a piece of code, you can, like, look in that bag and figure out what your ID is. Precisely. So, in terms of Sleuth, you have a span object on which you can get Trace ID. Right. So, this is this correlation ID on this whole business operation. So, that way you get it, like, immediately inside the code if you need to, for example, log, I don't know, do something about this Trace ID.

14:25

Because, in the logs, the Trace ID is always passed in if you're using Sleuth. So, always you get this value in the logs. So, afterwards, for example, in Kibana, you can search by Trace ID and you get all the logs from every single service that took part in this one big, let's call it, transaction. So, that accomplishes two things we were talking about earlier. So, one, if the developers do nothing, but they're running in this, like, a runtime that supports all of this, you at least can pull out from those log files, like, here's all the logging that happened, that are related to this, and organize it by a span, essentially. By a Trace. Yeah, yeah. By a Trace. Yeah, you can order by the same Trace. So, if in one, let's call it, business transaction, there are 100 hops between 100 services, then you're going to see all of those 100 services and their logs. Right. If you provide, like, I'm searching via this Trace ID, because this is what correlates all the services, the same value of a Trace ID. That's right. So, one Trace ID, but a lot of spans underneath. Got it. Yeah, yeah, yeah. Yeah, I've seen people do similar things with, like, Splunk Magic and other search, where, you know, you find some way of uniquely identifying all this stuff and filter down to it, essentially. So, this is exactly. Actually, at SpringOne, I'm going to show it in a demo together with, actually, Kibana. So, we're going to have a couple of apps. We're going to log some stuff in the apps and then present them in Kibana and sort them via, filter them via Trace ID. Ah, all right. So, the last question before we wrap up. So, you got all this technology, right? And we started with, like, what drove you to use it and everything. So, how would you describe, like, the theory of monitoring that this enables for you? Like, what – like, if I'm someone responsible for monitoring, like, one of these wacky microservices-driven systems that maybe also has non-microservices stuff, but it's all Zipkin-enabled, like, what do I – how do I use it? What does it feel like when I'm using sleuth-driven stuff to do my monitoring and remediation jobs?

16:27

So, when we're talking about Zipkin, Zipkin is a tool to monitor – to find latency problems. So, I would separate two things. Let's say, measuring, for example, KPIs from measuring latency. So, you can, for example, if you have a critical part in your system that's really important for you from the business perspective, you can wrap it in a custom span, a local span, and you're going to see the exact duration of this part. You can add tags, so key value pairs that will, like, help you understand more of what's going on in your system. But the thing is that with Zipkin, you have also sampling, because what that means is that not 100% of, let's say, traces are going to be sent to Zipkin, because you would run out of disk space. So, by default, by default, we sample 10%. You can switch on to 100, so every single trace, every single span will be sent to Zipkin. And in, like, how many, I don't know what to call them at this point, but how many user interactions, like, would you make that cutoff at? Like, let's say, in an application, and, like, people, there's, like, 100 uses of it in a day. I assume I would probably collect 100% of stuff, versus, like, there's, like, 100,000 uses of it. Of course, if you have, like, a bazillion requests per second, I would sample it, obviously, right? Because, yeah, I mean, you can have problems. I mean, if you think you won't, and you think that it makes sense, like, sample 100%. And then you can, like, profit from that in that way that you're going to see every single trace in Zipkin, and you can see that the crucial part of your system takes that much time. And if that is crucial for you, what I would do is I would, for example, wrap it in a, I don't know, for example, CodeHale metric sort of, let's say, meter or counter or whatever, and then measure that with this tool.

18:33

Why? Because then you can, for example, you send it, for example, to Graphite, and then you can have different tools that allow you to put a learning on that. Right. So, for example, you have a crucial metric for you, I don't know, amount of requests per second, whatever, let's imagine that, or no, even let's be more pragmatic, amount of money that the current service gives you, for instance. Let's assume that you can monetize the stuff. And then you create a metric with which you count the money, and then you can, let's say, put a learning that if you go below certain value, send an email or send a message to Slack or whatever, ping via PagerDuty or something. So there are tools that can allow you to do so, and that makes more sense because this is typical metric stuff. What Zipkin is used for is latency. For example, a user clicks around your system and says, hey, it's slow. What is wrong? Right, right, right. And then you can see, ah, yeah, and you can see the bar graphs, and you can see, for example, immediately that you have a very long bar. So it means that the request was very slow. Why is it so? And then you can click around, figure it out. So I would discern those two things. Yeah, that makes sense. There's sort of like point, not point in time, but single point monitoring of a metric versus what I would unfairly categorize as like weather reports, right? Like in the sense of like, I want to know how the system is doing in aggregate. Like your example is good. It's like people keep telling me it's slow. Like I look at the logs and I don't know. Precisely, you don't see anything in the logs. You would have to log every single method, call or something like that, the count, let's say the duration of a single call. Right, right, right. And this is exactly what you get with Zipkin. Right, right. So, I mean, those are the kind of like the two types of modes that you would be like monitoring a single point of things essentially and then monitoring kind of the overall health of a system.

20:33

Precisely. It's almost like quantitative and qualitative. Like the quantitative thing is like here's a bunch of data points that are exactly this. And qualitative is like, I don't know, it feels okay or it feels bad. Yes, precisely. So, that's what I would discern KPIs from the overall state of the system. Great. Well, great. Well, that's fantastic. That's a good quick overview. So, tell people like, you know, where you are on Twitter or you've got a lot on your blog too. I often interview people and they're like, I haven't updated my blog in five years. But I think yours is a lot more recent. I'm trying to be like a frequent blogger. So, like I said, my name is Marcin Grzeisztak. So, my Twitter handle is at mgrzeisztak. If you're not Polish, you're not going to even like find it. So, I suggest you go to my blog, toomuchcoding.com. That's right. Like, you have very chances of remembering that. And over there you can find my Twitter handle. And, yeah, I try to blog frequently about, let's say, microservices as such. Right now I'm trying to blog also on the Spring IO blog. And I'm trying to blog about stuff like answering difficult questions that arise. Like, how to do zero downtime deployment, for example, in terms of the database. Because with Cloud Foundry you can do magical stuff like CF Push and that's it. It's working. But you have to remember about the database, for example. Yeah, always the data. Yeah, how to deploy microservices, for example. Right, right. How the pipeline should look like. So, you can check out my blog. Well, great. You could find a lot of answers there, I guess. Yeah, well, I appreciate it. We'll, as always, have this at soundcloud.com slash pivotalconversations and at the blog at pivotal.io slash podcast. Maybe you need to put a blog in front of there. I don't know. Just search for pivotalconversations. People will find it. We'll see everyone next time. Thank you.

Tanzu Talk · 🍕 Get more pizza.