Cloud Native Computing Foundation EnvoyCon North America 2021, 30 Oct 2021

Previous Meeting Next Meeting

⏯

youtube image

►

From YouTube: Connecting the (Proxy) Dots: A Beginners Guide to Reading Envoy Debug Logs - Casey Kurosawa

Description

Don’t miss out! Join us at our next event: KubeCon + CloudNativeCon Europe 2022 in Valencia, Spain from May 17-20. Learn more at https://kubecon.io The conference features presentations from developers and end users of Kubernetes, Prometheus, Envoy, and all of the other CNCF-hosted projects.

Lightning Talk: Connecting the (Proxy) Dots: A Beginners Guide to Reading Envoy Debug Logs - Casey Kurosawa, Ambassador Labs

In the world of support engineering, one of the most valuable questions you can answer is "where is this problem coming from?" When it comes to debugging Envoy Proxy-based applications -- where the traffic can be coming in and out, backwards and sideways -- it can be particularly difficult to answer this question when you’re trying to figure out why a request is failing. This talk will provide a brief overview of how Envoy is structured, and then conduct a live walk through of the debug logs of a request. Attendees will learn how the information in these logs relate to Envoy's internal mechanics.

A

That's so welcome. um I hope you guys are having a good envoy con and beginning of kubecon, um so we're already starting a little bit late. So I'm going to try and rush through this uh see if we can get to the meat of this a little quickly.

A

So um my name is casey kurosawa, I'm a support, engineer or solutions engineer with ambassador labs um and we're going to be talking about envoy, debug logging.

A

um So I started my journey with envoy um a little more than a year ago, starting working with the now emissary project and working with clients and customers using our products and trying to figure out problems that they're having and you know the default envoy logs that that come with uh the the the system are, are quite helpful and you know very useful, but sometimes you want to dig a little bit deeper, but once you turn on that debug logging mode, uh you get flooded with a sudden massive wall of text right once you once you take a look at it.

A

It's a lot to take in it's very overwhelming at first, and sometimes things aren't, even necessarily in the order that you're expecting them, of course, because because envoy is a multi-threaded process and is able to handle simultaneous requests.

A

So getting an understanding of the overall architecture of how the logs are structured can help us follow requests. So let's break it down and start one line at a time here.

A

uh Looking at each individual aspect, we have the time stamp, which is pretty straightforward. We have the worker pid that's associated with a particular log line.

A

We also have the log level the component that is associated with it, and so this could be maybe a filter component or routing component you're, most likely going to find.

A

um You know these kinds of these kinds of uh this kind of information here, you're also going to get the code source of where this particular action is taking place, and then the two pieces that I find the most useful are the connection id and the stream id and now by utilizing, both the timestamp and the stream id we're able to identify a particular set of of information about a request, as it's passing through the data plane, the envoy data plane and then finally, we can tie that request information to a particular action that takes place so now.

A

Let's actually follow an example connection as it passes through envoy.

A

So first we have the initial handshake. You can see as part of our logs here that we start out with an initial tls handshake. It provides us the server name that was requested by the client, and we can see that after accepting that handshake, it initiates a new connection.

A

Now, after the connect connection has been established and we can see the particular connection, id is c2988.

A

It establishes a new stream and processes, the headers now a couple of interesting things to note here. The first, of course, is that we're utilizing our http 2 pseudo headers here, so any kind of identification of the the host header is going to be part of that authority, uh pseudo header as you're looking at it.

A

The other thing is that you're going to also see a number of the um various user agent and information, that's being populated by the browser as well, and this can be another good way of identifying a particular request that you want to take a look at, and so at this point we can now establish that's the uh initial request that has come in and it has been processed and we get the header information, that's associated with it, and now because our proxy is utilizing the xdot filter we're going to take a short side track here, and this is going to be the case for most uh filter filters envoy filters that you have associated with your envoy instance.

A

um So in this particular case, we have an upstream xdoth at localhost, port 8500 and it's doing a post request, and we can see that it is able to send the contents of the request and get an authorization response back, and you can also notice that it actually establishes a completely separate connection here with a completely separate stream id. And so this kind of gives you proof uh in the actual logs that you know. This is an actual uh synchronous process that that is happening uh separately to what's happening. With your um request, connection.

A

And so now that we've established that this is uh authorized as part of our xdoth, we can now construct the proxied request that is intended for the upstream, and you can see that this will be the final contents of the request as it gets passed to the upstream cluster, um including all kinds of uh header modifications, um you'll notice that we get our x envoy, uh headers automatically attached as well, and so those can be inspected to see how those are interacting with the system as well as some information.

A

If you were to look at the actual cluster in something like xds, you can see which specific upstream cluster is being matched for, the particular url and for what information and now finally envoy will actually construct a new connection, typically the the user, using the number following uh the initial request and is able to establish a new connection to a this upstream um and receives a response back that it then returns to the original client and after the response is complete, and it is established that it is finished.

A

Sending this 200 response code. We see that it destroys the stream and completes the connection.

A

And yeah, that's that's pretty much about it. So, as as kind of a general idea and- and the final takeaways here is- is that um by understanding how to read the debug debug logs and in particular, how to associate these particular uh connection ids and stream ids, you can see the full process by which envoy is able to handle uh data and handle network connections and get an understanding of um the overall architecture and the overall process by which uh envoy does its thing.

A

um So, finally, just as a special thanks to ambassador labs, the company, I work for special thanks to envoycon and kubecon, as well as daniel bryant, who helped me in making this presentation as a side note quick sort of plug. We are hiring and there are some links for more information about ambassador labs. Thank you.

A