Monitoring NodeJS with Open Source

[00:00:13.920] Good morning, good afternoon, good evening. I'm coming from sunny Birmingham, even though you can't see it because of the closed blinds. So I'm here to talk about monitoring Node.js with open source. It's quite important in reality.

[00:00:28.480] I am Mike Elsmore. I'm Developer Advocate for Logz.io. If you wish to get a hold of me, there is my email and my Twitter handle, which also happens to be my GitHub as well. So feel free to send any queries during or after this session.

[00:00:46.520] So what is the problem this is covering? Well, it's Node.js, or in reality, it's just JavaScript, because some of these can be applied to the front end as well.

[00:00:56.840] If you'd told me 10 years ago you'd be seeing JavaScript everywhere, I'd have probably laughed, but now you do. And we're not just shipping one huge chunk of it every so often. We are more, in reality, shipping hundreds of smaller components: be this in Docker containers with full Express stacks or Hapi stacks. We're shipping Lambdas. We're shipping Azure Functions. We're shipping components, pieces, different bits to different places. We've got backend workers. We've got front-end code. And all of this is producing data that we need to keep an eye on.

[00:01:38.580] So we've got all these hundreds of components, and there's a lovely little meme that I've been using recently to describe it, which is just, "Lambdas, Lambdas everywhere." Because when you start shipping one Lambda, you end up shipping hundreds of them. I personally really like Lambdas because it allows me to play with tech quite quickly and quite nicely.

[00:01:59.180] So when it comes to monitoring our systems, well, we're all quite used to just dumping stuff out to console with JavaScript. So just going `console.log`, or attaching it to a log file and just leaving it be and just having it dump out. Or at least that's what a lot of people are in the earlier part of the 2010 era, where we were just throwing stuff somewhere else to think about it later. But what's the next step? How can we monitor our systems more effectively and with more insight into what's going on?

[00:02:37.880] That would be, in my opinion, observability. So it's not a new term, it's not an old term, but just for those who aren't aware, here's what it is. It's made of three components: metrics, logs, and traces.

[00:02:53.460] Logs being the historical information, specifically on what's happened within your system. Metrics are more of what is going on right now. And traces, which we're not going to really be covering too much in this session, because 20 minutes is not long enough to cover everything, unfortunately. Traces are the end-to-end flow of data and information, how your system is interconnected.

[00:03:17.580] This is hugely important in large distributed systems that we see these days. Everything from the wonderful graph at Netflix of all of its microservices and all things like that. It's quite important for us to have knowledge of not only what the individual component is doing, but what the side effects of all of them are.

[00:03:40.020] So a lot of people are going, "I don't need this. The JavaScript I do have, it's not really doing a lot. It's just sat there." Or, "It's only the front end." Or, "It's a little Lambda validation on an S3 bucket." Or, "It's just a connector for the Lewis APIs to connect to something else, so we don't really care."

[00:04:02.960] Well, in reality, you probably should, because even if it's a small component or piece that you don't think of every day, it's still within your system, and you should probably be keeping an eye on what your overall system is doing.

[00:04:17.640] So let's start with the easy mode. This is the one that everybody's pretty much always aware of and has access to and has played with before, especially when things have gone bang. So event logs, it's fully easy mode.

[00:04:30.100] This is just immutable data with a timestamp attached to it. The common structures here are plain text, so just strings in the usual formatted version, say, the Apache log format or something like that. We then have structured. So that is usually JSON objects. We're all used to seeing these as well. You can, in some systems, see them as XML, which I always find a little odd because that's a lot of extra gumph to be sent over the wire quickly. And then there's binary, most commonly in Protobufs. I haven't seen it recently in a lot of systems, but I did used to see it in some programs which used to just dump out Protobuf information, which, oddly enough, I never actually debugged against, just saw what the output of some of the applications I was playing with were.

[00:05:18.240] As we're talking about this in an open source context, the best open source that we have available to us, for most of us, and especially me at Logz.io, is the ELK stack, which is Elasticsearch, Logstash, and Kibana. Logstash isn't used that much anymore, especially with the advent of the Beats system, especially within the logging service, which is Filebeat, which just grabs and streams a log file to Elasticsearch.

[00:05:52.620] So Elasticsearch is the storage engine allowing you to do indexes and looking up on the different levels of log you have. Logstash is the transformation and shipping component, which thus Beats is as well. And Kibana is the visualization engine, the way you can look at your data and get more insight into it, rather than just seeing lots of logs which you need to search through.

[00:06:19.328] Then we've got system metrics. Now, not completely around monitoring, but in my eyes, still a very important part of it because it's telling you what is going on in your system right now.

[00:06:33.988] So these are, once again, immutable data points, but these are more numeric information. Log data is what's happened, and most of the time it's strings of information and long formats: failed files, memory over-usage, or stuff that is a string format, something that you end up having to search for. These are more numeric, more defined values that you can use. So usually consisting of the timestamp, the label, and the data point associated with it.

[00:07:04.788] Now, the common ones, especially if you're using the system-level metrics, are CPU, memory, I/O, network, and all of these can be displayed as integer values. So you can graph them and see performance as is in real time of how an application is behaving.

[00:07:22.008] In the open source world, the best tools for this are Grafana, which is the UI and control layer on top of a data source. Internally, we have this as a product on top of the Elastic Stack. So we have Grafana connected to Elasticsearch with some custom code in between to improve time-series performance.

[00:07:44.528] The most common is actually Prometheus, which is a complete stack and ecosystem in upon itself, using PromQL as a querying language, and it has a UI of its own to help you interrogate and work through the data. At Logz.io, we are actually working on a PromQL-compliant version. However, don't ask me about any of that. That's the product roadmap side. You can talk to somebody else about that.

[00:08:09.948] And then there's tracing, which is hard mode. It's the thing that most people won't have used or come across, but it's still important.

[00:08:20.828] It is the end-to-end flow of an application. It consists of traces and spans. The traces are the actual path that the information is taking, so entering an API gateway or appliance at the front end, then hitting the next object. And sometimes those are different services inside your application. Sometimes if it's, say, a very large service, it'll be individual parts of the code base as well. And those individual blocks are spans, so you can see where things are taking their time.

[00:08:52.688] I'm going to go back to AWS because that's one that I most commonly use. Say you have API Gateway going into a Lambda. You then have it firing off to store in S3, and you have an S3 trigger, and that S3 trigger then grabs the information, throws it through a Lambda, which is programmed to take part and use a recognition service and then process it, and then throw the information back in. You can then see in that flow which one of the components is taking too long, and then you can analyze that component independently and see if that is a performance issue, or an issue with some bad code, or the actual data that's going through it.

[00:09:36.508] But that tracing system gives you an overall view of where the bottleneck may be and how the individual components are impacting each other. This is, as I've written here, best used within microservices, but can be used with service designs in general. So service-oriented architectures where you can have different services, but they may be monolith or anything like this. You can still use it, and it will still provide you value. You can think of it more like profiling and debugging, but on a complete system view rather than just a single application pipeline.

[00:10:18.068] So the best tools for this: there was actually three, but I never put one in because I've never used it, and I don't know enough to be able to answer questions about it. There's Jaeger, Zipkin. There's also SkyWalking, but I've never used it, so I try not to mention it and get caught up on it.

[00:10:35.428] Jaeger and Zipkin are the big boys within the distributed tracing space. So Jaeger is a project that was spun out as an open source project from Uber. And I don't know if they're still using it, but they were using it at huge scale to monitor their internal infrastructure, and they had a network graph in one of their talks which looked just as bonkers as the Netflix one. And Zipkin, if I remember correctly, it was spun out of Expedia or something like that. Same principle, really: just the tooling they use to keep an eye on their huge internal infrastructures, which they then just open sourced.

[00:11:19.528] Jaeger is getting a huge trend, and considering it's so easy to implement because you can just roll it as a complete stack in itself, there's no reason for you to not try. But we're going to skip over that with the next part anyway. So here we go.

[00:11:37.128] Demo time. The thing that proves what I'm going to be talking about, I hope. So we're all used to logs. Oh God, demos, I'm always worried.

[00:11:51.368] We're used to logs. So I have a quick Lambda app that's just doing some stuff to produce some data to prove my point. So we have here using the Serverless Framework because it makes my life easier. We have a bucket that things are being dumped into and out of. Yes, I'm using the Hello function as my initial input. Some of the reason: I couldn't be bothered to change the name.

[00:12:18.308] This one is going to be grabbing information from Giphy and throwing it into S3, and then the S3 one is going to be grabbing that file and then producing a single-frame thumbnail for me, because how else do you produce random meaningless data? We also have some more stuff down here, which I'm going to example in a minute, but we'll start with the logs.

[00:12:40.448] So in a handler, we can go one step above `console.log`, or keeping a well-formatted structure. With JavaScript and the application stack that it's using and all the different places it can be shipped to, you can intercept the logs at so many different layers.

[00:12:59.868] For example, if you're using like this, it's a Lambda. You don't have access to the host, so you can't stick Filebeat on the host and stream off a log file. You can't just intercept. You don't have access to the host. You can't stream the Docker tail to be able to read from a Docker container it may be in. You don't have access to all that in the PaaS layer. You may in the IaaS layer, so something more like EC2s, for lack of a better word. You can actually get a hold of the host and be able to stream the information from the host, so you can use Filebeat or the components. Or you could, if you're using bare metal, just control everything and it's fine. You can intercept it at different layers.

[00:13:50.368] But because, for me, I try building my code as if I don't know where it's going to be shipped to, here we go. It comes with a nice concept called transports within the common logging libraries. So I'm using Winston because it's one of the more common ones, and it produces a very nice JavaScript JSON format that we can use inside of Kibana.

[00:14:15.248] And we have our logger. Now, this logger I have actually configured to do two things. One is throwing all statements that are debugging above to the console. Now, as it's in a Lambda, that means it's going to end up in CloudWatch, so I have access to all the information in CloudWatch, regardless of how important or how unimportant it is.

[00:14:36.548] I'm also sending it via the Winston transport for Logz.io. I'm sending it to the Logz.io service, so we're going to have access inside of the ELK stack to play with. But there, we're only sending info-based logs to play with, and we're going to be able to look those logs up based upon the application name, which is handily called `node-lambda-observability` with its version number. Just to make my life easier, but hopefully we won't need to worry about that. And it's only throwing info level.

[00:15:06.868] So we only want information that's more pertinent. We don't want just the random debug statements of how large one of the GIFs is or anything like that. We want the success metrics. Has a Lambda processed? And the errors, because the errors are more important. We want to know when something's gone bang.

[00:15:22.868] And there we go. The Lambda is doing that. We've got a bunch of info statements, some debug information. It's all being thrown through. And it's the same with the post-process one as well. It just produces more data.

[00:15:35.328] So if we go to Kibana, we can see we are getting lots of lovely information. I have got some other experiments on here running as well, so I apologize for the extra junk. But we can see here, so if I click Type and `node-lambda-observability`, add that tag, and now we're only getting the logs that are coming directly out of the application itself. And we can see that it's coming through with its log level, and it's coming over with the correct tags and the timestamps, so we can do information with it. Then we can do work with it.

[00:16:16.548] That's the quickest way to show that. Just as an FYI, if you don't want to have to do all this internally because you don't want the extra overhead that the transporters may incur, which they can incur, if you go to our docs and you wanted to send data directly from CloudWatch, there is a way of doing this. I'm not the biggest fan of how it does it, but it can be done.

[00:16:40.608] AWS, and we've got CloudWatch. And this is a Lambda that's coming in and grabbing the information from CloudWatch every minute and sending it through to the Elasticsearch instance we have to run against. I do actually have this one installed because I wanted to play with it myself and make sure it's working. So I actually do have it here running. It's just a little Python Lambda, which is grabbing stuff off the CloudWatch logs.

[00:17:12.988] Yeah, there you go. That CloudWatch Lambda is all the S3 messages. So if we didn't want to collect it from within the Lambda, we didn't want to have to do the extra work, we can grab it just straight off CloudWatch in the background.

[00:17:26.528] We can also do some quick visualizations because I like visualizations. We can just get some decent value out of that information with the Elastic Stack. Where is my... Let's go with heat map. Heat map's a nice one to go with. Count shows you everything. We want the X value to be, let's make it terms, so it just comes out with things at a log level. If I can find it quickly. Level. And metric count.

[00:18:04.248] Oop. No, I've done it onto the wrong axis, haven't I? Yes, yes, I have. Anyway. I only have a few more minutes to quickly show this. Let's get that back up. Level, metrics, add sub-bucket. Y-axis aggregation. Date histogram. We'll play. And well, that means too many series defined. Let's try this again, shall we?

[00:18:51.498] X. Date histogram. Apply. Last 15 minutes. Excellent. Add sub-bucket. Y. Sub-aggregation. Terms. Scroll to level. Play that. And now we can see we are getting where the logs are being produced in info, error, and warning at different parts of the application.

[00:19:23.438] It's not really insightful because unfortunately we can only see the 30. So if we just quickly switch the options, increase that to the maximum of 10 and play again, we get a slightly better indication of where our errors are appearing, at what time, and whatnot. So we can see where an application's going to be producing too much error information. That's something we should definitely investigate.

[00:19:44.328] And just as an aside, there's the metrics. We can do the same thing on our Lambdas. So we can just see where all the information is and see how performant it is and how things are playing out. So we can see if something's performing badly.

[00:20:07.648] If you do want to work with this in the more of an open source approach, there is OpenTelemetry. Now that is now tracing and metrics going into GA in the not too distant future, and logs coming around after that. But this is a standard specification which will allow you to, regardless of vendor, ship information from A to B and do all of your system monitoring.

[00:20:29.548] So if you want to, go to opentelemetry.io and have a look into a wonderful open source project that's driving all this forward. And if you have any questions, feel free to fire them at me and I will do what I can to help. Or if I don't know, I definitely know somebody who will.

[00:20:47.308] So thank you very much for listening, and I will hope to see you on the internet. Goodbye.