GitLab Support Team, 28 Jul 2020

Previous Meeting Next Meeting

⏯

youtube image

►

From YouTube: Using Strace to Understand GitLab - Part 4: Gitaly

Description

A walkthrough of straces of two Gitaly requests.

0:00 FindCommit - a typical Gitaly RPC
8:04 UserCommitFiles - complex Gitaly-Ruby RPC
12:08 Gitaly InfoRefs cache invalidation
15:26 GitalyRuby requests to main Gitaly process
20:10 Pre-receive hooks
28:55 Update hooks
34:00 Post-receive hooks
37:39 Regenerate InfoRefs cache

Part 1: https://www.youtube.com/watch?v=fcY5pPUq35U
Part 2: https://www.youtube.com/watch?v=tThs8QeP2qY
Part 3: https://www.youtube.com/watch?v=J-GkU7Mmqy4

A

Hi everyone: uh this should be the last s trace video, so this one will go into um s, tracing giddily and understanding. What's going on there all right, so let's go ahead and get started. um So I will first do a real, quick request and then we'll do a more difficult one more complex.

A

All right, so, let's just give it here.

A

A

A

Okay, that off and we'll just pull up this repo, which is on our gitly server. So this particular.

A

Gitly instance is remote, so it's not on the app server it's on a separate host which is connecting or communicating over tcp with the uh the actual rails node. um So if you look here, that's just what I want to do is find a fine commit, because that's a pretty quick and easy uh request. Okay, here we are so find commit, um so here we're reading it on port 8075, here's our remote ip address and so like we saw in the last video here- are the basic fields.

A

This is actually you know just like the request we saw on the other one. This is you know what we see on the other end of the wire right, so here's the the actual rpc we're calling here's our error. Token client name is gitlab web because it was triggered by the browser.

A

Here's our correlation id session id deadline type is regular.

A

Here's our path to the storage product, number project- name: branch- okay, all right! So we read that over the wire. Then we check if there's anything else, we have nothing comes back so then what kindly will do is it will start validating that these directories exist? So let's say: does the base directory exist? What about the objects directory and then we check if the refs directory does the head exist and packed refs which may or may not exist? Typically? Well, um okay!

A

So that's the first thing we always do whenever an rpc comes in. Is you just kind of validate these directories that exist in those files, but because skeletally is written in go and it's uh go? We'll typically have an eight threads per process. um You're going to see what happens is that what process or pid in s trace is doing the work jumps around a lot, and so it can be hard to follow.

A

Okay, all right! So 8623 is our pid, so you can see that it does that it creates a pipe which I think is going to use to communicate with the get process and it creates an e-pole to wait on something I guess the pipe yeah and then catch. It creates a few more pipes, presumably for a standard or another one. Next to me for standard error, I guess um actually creates three centered in out an error, yeah all right. That makes sense. Okay, um then down here it gets its pin.

A

So this is the actual pit that you'll see in ps is one four three five five and this is just happens to be thread. Eight six, two, three, that's doing the work here, all right! So then eight six, two three clones.

A

um So let's actually go to the end of that first and you can see that it comes back with, uh in this case it's creating a new process because uh we don't have the clown underscore thread flag in here. um Also, this clone v4, which is a good sign, that's a new process, and so anyway, so here's the process number we get back. um You can actually see that 26 or 27634.

A

You can actually see that here it starts up before the clone finishes right, so the clone can't can't actually give return with the process id until uh the new process is actually spun up. So let's just look at the new process now 27634.

A

All right so because it was cloned, it does the rtc action where it sets all the signal handlers. So you can see a big block of those right at the start.

A

Like I mentioned in the earlier videos, that's a good way to tell that you've got a new process coming up, um and here it's setting up its standard in and then standard out and then standard errors. So it's taking these pipes that I got from its parent process and using them to create its input and output pipes and then at that point it then execs get here's the git directory that we're using and we're doing a cat file batch.

A

So catfile batch will. Let you pass in refs and you'll get back the actual contents of that uh of that file or blob.

A

Okay uh or commit which I guess find commit is probably going to return a commit. Isn't it okay uh and then, at this point we're doing what we saw in like get video? We um we check whether, where our heap ends when we start loading, our shared libraries, I'm just going to skip past all that, since we haven't seen all this in detail previously uh literary git configs, and here we start loading in the get directories.

A

Let's get past all that, and this should be pretty quick um just because basically, it's going gonna do almost no work here. We're just gonna, get a single commit back, yeah, okay, um so here uh we write out that we gotta commit, and then here are the details of the commit and then we get in here's another commit to print, and so we've printed out details of that as well.

A

um Yeah, no, okay, actually rewrite that out. Let me write out this, which is okay, yeah, all right. So this what happens here is so you write out this output that goes to gitly. Let's actually look at that more detail here, all right, so we're right up to our standard out here. Here is the sha, and here are the details and then 8623, which somewhat surprisingly, was the process that forked all this in the first place, is the one that picks that up. So it reads it off.

A

You know you can see it's a big chunk of data here and then here it writes out okay to find commit, so we've actually finished at that point. um That's a little interesting. Actually that makes sense yeah. Okay, all right! So then what are we actually putting in the body of the response here yeah here? It is so here's the body of the response, and you can see it's just encoded, the data that we got back from get. So that's fine comment, that's quick and easy!

A

Basically, we just have this grpc level over git, so it comes in gateway, fork's, new git process. Git then, does exactly what you saw with the local get pipes that back out to gita leak. Italy then does some minor transforms on it and sends it back over the wire out to gitlab so not too complex um once you know what git is doing and um pretty easy to follow all right. So that was the easy one. Let me.

A

A

A

A

Okay, great uh all right, so let's s trace skittle again.

A

And this time, what we're going to do is we're going to make a change via the web ui and we'll see what that looks like.

A

A

So esther is kiddily.

A

Okay, that's done now. Let's actually take a look now, um let's, what we'll do first is.

A

We'll okay, uh here we are okay, so just to give you a quick idea of the structure of a request before we dig into the details in s trace.

A

So this is a gilded request, so the gitly, normal gitly uh worker, is going to take the request and it's going to write over a socket to getalyruby, which is a ruby process, as you might have guessed, which is multi-threaded and so it'll have one listener thread which will then pass it on to a worker thread and then we'll kind of do three steps we'll run our pre-receive hooks go to the actual commit and then we'll do the post receive hooks.

A

So you can kind of see that this is the the structure of the of how it works. So these pin, ids or pins in brackets or threads ones without brackets, are full processes. So this is the one four four four five is the cable worker that gets the request. It then launches the pre-receive hooks, which does some work and then roll right out to.

A

Let me also do the update ref um we're gonna update head there. I guess yeah, and here we are yeah right there, we're updating the update right for the kit and then we're doing post receive I'm not seeing.

A

Well, we'll see that we'll go find that when it gets to it anyways, that's the basic the basic uh over the over the view of what we're going to do, we're going to run pre-receive hooks we're going to update the ref, we're going to do post receive hooks um and we're going to see the same basic pattern, particularly as previously imposed. You see folks of what happened. So, let's actually dig in into the s trace itself and see what happens here all right, uh so this is user. Commit file was the rpc recalled all right.

A

So here is the the main gitly process. Reading that off the wire port 8075 user commit files, uh we can probably see blah blah in here somewhere. Maybe no, I guess not.

A

A

Here's the actual details of the push okay, so first thing to go into is um as of 12.10, italy will cache the refs for a given project to make it more efficient to respond to http requests, and so, whenever a request comes in that modifies the the refs for the project so like like making it push, you recommend we need to update that cache.

A

The first thing we do is we delete the latest file here, so we use unlink at to delete that, and you can see it's in this- uh the basic repository directory and then plus gitly, the state then hashed that and so on from there. um So, basically we're saying the the the cache state that we had there is no longer valid or deleting all these files and then from there we can go into the standard new f-stat ad that we saw earlier. Actually, no, this is still for the cache okay.

A

So we validate that these directories exist. Then we start making that directory tree again, although in this case I think they already existed so that we shouldn't do too much work. There.

A

um All right, and then we created this new file here.

A

Okay, yeah all right now here, so we kind of created this. This is going to be the pending refs change, so we're not going to commit that until after everything's done, though, so it just kind of hangs out there until we're done with everything else. Okay, let me close out the file handle, and now we can start doing the new fs to add that we stop at the start of the find commit request. So we validate all the trees. Are there um and then here we're actually writing out this the same pit yeah.

A

A

Yeah, okay, we write out to the rails client here I guess just acknowledging the response.

A

I guess we do that after we've cleared the cache- and now here are writing of our unix socket, which is going to be going to gitly ruby, and you can see down here for whatever reason that asterisk doesn't capture what the path of that file is from the sender. But you can see down here that this is in fact ruby1.socket. So this is gili. Gilly repeatworker1 is getting the message back or getting the message over that socket from the main giveaway go process, and so you can see it's.

A

Add new file, here's the server details and so on same basic content that we saw above all right, so one four four two six reset in, but it doesn't actually do the work. It just just reads that socket and then we pass it over like we saw in the parser output over to one four four, four five and there's no explicit syscall here, because it's all within the same process.

A

So you just kind of have to watch for what process or what what pit here starts getting active um so based on between the parser and just seeing 1445 start working. We know that's the next one that actually can work. Okay, so 1445 is going to do most the work, I believe uh yeah. So, let's just.

A

Narrow that down, uh okay, and so what's the first thing it does. uh It's writing this out. Oh that's for any poll. Okay, we can ignore that.

A

Okay, we create a new socket and then we are connecting the port 80 75 to gilly itself. So basically, what happens here? This is a really common point of failure. um Something to be aware of is that this gilly ruby request in particular needs to call into the main ghillie process before as part or as part of their collecting the data it needs to actually go out and do the request. So the first thing it does is connect to the main guilty process using the address set in the rails, server config right.

A

So that's that's that's passed as part of the header and grpc. So that's how it knows how to connect to the gitly server. Now, keep in mind that if we had multiple giveaway servers, we might be connecting to an entirely different one, for whatever reason, if it was a fork, for example.

A

um So in this case, it's the same server because you only have one, but if, if it's not, if gilly is not able to connect to itself, then you're just going to get a really generic error, which is not common but really hard to figure out when it happens.

A

uh Okay, so we we are trying to connect over udp for some reason. First, that fails because we're not listening on udp and we try again with ipv6 tcp and that does connect eventually.

A

We saw most of this pattern in the uh the puma video, so I won't go over in too much detail. Let me send a message, and uh can we actually see the rpc here? It's not obvious where the rpc is okay. Here we are yeah, so it has. Local branches is one, and if you look at the search code, you can see all this, um but frankly the gitli resource code is kind of convoluted.

A

So it's often easier just to look at stress to see what we're doing.

A

Okay, so we've done that, then we check our references. We just we create a new connection again and now at this point, we've gotten the data we need from the main gitly process and gitly ruby starts opening up the rebooted itself, so it starts studying the the get get depository or repository path. um So, instead of using get here, we're using rugged, which is ruby bindings to libgit2, which is a c library that basically is but is works like git, but it's not actually get proper.

A

um We use both gitlab, but you can see it's the same basic process. We make sure the directory exists and read the configs. It's you know. Look at two is supposed to be entirely feature uh impeachment parody with regular get okay, so reader configs uh reading our pact reps here.

A

Okay, well, actually we're still going out to main gilly process again. Okay, so I'll skip over most of this, because this is what we've seen previously: okay, um all right. So we've gotten to this point where we are writing out a temp object. So here we have our temp file name like we saw earlier. We make a directory.

A

Now we write that.

A

Right to the temp object, or it's more of the temp object, fair amount of data there.

A

Fsync here to make sure the change goes through, I don't think we saw that was the local get. That's something you can set in your config and by default. Gitlab does turn that on which is good, helps print data loss. Okay, then we rename the temp object. The real name, we've seen all this before all right. Let's just skip ahead a bit, because this is a pretty long request.

A

Okay, so we've closed our object, but we haven't actually committed anything yet and here's where we start firing off the forks. So here you can see, we see ruby, calling v fork and we get pit28271.

A

So here's 28271 it takes signal handlers, changes directory to the repo directory, and here we exec the frequency folks.

A

And then immediately we start cloning. Here you see the clone thread, field or flag being passed, so we know this is not actually a new process. It's a thread for that process, uh all right and then we're writing out. This is kelly review process. Writing to the the prereceive hooks, here's, the old ref, a new ref and here's the ref that we're changing.

A

Okay, here we load in our.

A

Shared libraries: I think this is just a shell script. We can look at it, but I'm lazy yeah all right. Let me start opening up the hooks here.

A

Maybe this this might have changed recently, actually not to think about it. I think we switched over to go, but it was breaking things, so we may still be in ruby.

A

Okay, we're still doing some setup here and we cloned a new process and still two two eights and one we're just changing our that we exactly eat here, didn't.

A

A

A

Okay, another thread um here we are opening up the gilly hooks log.

A

Getting our locale.

A

Let's just go down to 28271 for now.

A

Okay, here we're writing it to the gitly internal socket. This is new. I think.

A

Yeah we haven't actually in there.

A

Okay, so here this is presumably the main gilly process. Reading on this internal socket writing out a short message.

A

A

A

A

Okay, here we are so now we are injecting the pre-receive hooks in gitlab shell, um just as a reminder so yeah. So here's one four, four, four five here we launched the kiddily hooks which in turn launches the gitlab shell. uh Actually it's pre-received, let's get that shell.

A

All right is this one that does two: it might be.

A

Okay, ruby get that shell hooks perceive okay.

A

Oh yeah, okay, it's playing base name here just to get this.

A

A

Okay, actually here we see that, but not there all right anyway, let's get back to the business and okay, so we launched a pre-receive hook.

A

The shared libraries standard preamble- I read proc okay here we start.

A

Yeah, this is a review process, so we can see it loading in all these. All these shared libraries. um Actually we haven't gone to the gems. Yet, okay.

A

All right, just looking here to see if we have any other peer receive hooks to run. So if I had a custom hook, then this is the point where we start triggering them.

A

I don't have any on this particular host, so we just keep going, and so here you can see the kind of standard pattern for ruby when it's first loading up the library is that we'll need to go in and load each of those files at runtime and it'll kind of walk the tree and so you'll see a ton of eno ant calls responses here.

A

That is normal for that to happen when a library is being loaded, that's just the way ruby works, um so it looks bad and it's it's therapy way, but uh it's not unexpected with ruby.

A

Okay, so there's gonna be a lot of this. Well, we keep loading, lots and lots and lots of ruby files. Here, I'm just gonna skip down.

A

Okay, here we're loading in the uh cert bundle that we bundled with gitlab. So all the search that we show us by default, um we're loading openssl, http helpers, all right- and here we go all right. So at this point the pre-receive hooks. This is another common point of failure. Is they make a call out to the internal api, the internal allowed endpoint to say this is what I've got?

A

Am I allowed to do this, and then we have to wait for rails to get that request and respond back um to confirm that the user and this change is allowed. So in this case we get the response back pretty quickly, but it's not unusual. I mean I mean that unusual is the wrong word, but it's not unheard of for that to take a long time or to error out. So that's another common place that this request can fail.

A

um Okay, but in this case it works and let's go down yep. So let me log out to the gitlab shell log that everything's.

A

A

They're actually sending another request.

A

Yeah, okay, then we call the internal pre-receive endpoint.

A

And we log that's okay as well: okay and then the pre-receive hook, exits.

A

Okay, so that was 28278.

A

So we've run the pre-receive.

A

Hook, go to the post receive hook and the update.

A

Okay yeah, so this is actually, I think, brand new with 13.2. We do this in uh and go this used to be on ruby things. Keep changing all right um so here that although pre-receive hook clusters are exiting- and you can see that the the ruby worker gets the sick child, that's children have exited, so the knight wakes up and starts doing the next job, which is the update hook.

A

So now I've got we've done the pre-receive hook and I'm going to do the update it's going to be the same basic pattern uh right after the internal.

A

Socket we forked here here it is we've forked.

A

And um looks like 28285 is the new.

A

Yeah, okay, so here we do the gilly hooks.

A

Update set our signal, handlers.

A

A

Create our thread.

A

I think we are.

A

A

Okay, let's see what the thread is doing here as well: okay,.

A

Yeah, so then we write out sending another rpc to the main guilty process over internal sockets, that's kind of confusing that we're both using the external and internal side or connections for kidly. Here, depending what we're doing um that's like, I said, that's new, so we're seeing this for the first time.

A

Okay, so you read off the socket um and then we're gonna see this time. Let the hooks and go do the task. Okay, so 14361, actually 28294.

A

Yeah, okay, so here again we see the hooks.

A

Yep and there we are ejecting that here are the args, we're updating the master branch, old, ref, new ref, okay,.

A

Great, we load in our many ruby string, error files. Let me see the same things last time. We should need to go out. The network though uh come on there. We go okay, uh all right, so we didn't get like a shell config.

A

We seem to have done nothing yeah, let's just go, buy something.

A

Let's just stop filtering.

A

There's a child exiting: where did it do its work.

A

Yeah, so here we're checking if there any update hooks, which they are not.

A

A

Must be missing something here anyway, so we can see that it did work um and then we're actually even trying to kill that file or process, even though it already exited.

A

Let's go up a little bit, and this is bothering me.

A

It's going to be loading in review.

A

Files, okay, well, this video is already long. So, let's, uh let's move on, I don't want to take all day all right.

A

Yeah all right, so here we are we're doing get update. Ref, I'm going to read the question from standard in get in all the shared.

A

A

And then the standard right to the head.lock and then rename and unlink like we saw in the other video all right, so we've updated head so now we've actually committed the change to the new blob in git.

A

So as far as gets concerned, we've actually made the change. um So now we just need to run our poster seat folks, and so you can see once again one four four five um picks up again and starts doing some work and before get another process, and here we have posters efforts and so once again it'll be the same pattern.

A

um We get the base name for that. I think we're going to exactly that here. Yeah here we are all right. So I'm going to get the hooks plus receive.

A

Recording process at some point we're going to go to internal and socket. I guess.

A

Here we are okay, so we write out that regarding processes yet again.

A

Okay- and at this point I don't think that a failure would cause anything to roll back. So I don't actually have any posters efforts in here, so it should be just loading up, ruby and exiting like you'd expect.

A

Just scroll through this wall of text we're actually making an external call.

A

Okay and there's no other traffic on this instance, which helps keep the noise down. So if this was nest, traced from a production instance you'd see all kinds of traffic coming through, which would make it much harder to to follow. What's going where um oh, what we're going to call the internal post receives. One point: aren't we okay, let's find out okay here we are yeah, so let me call into the internal api for the third time this in this call. This time we call post receive.

A

uh To fire off all the post receive actions which you know would be like: creating a new merge, request and stuff like that.

A

Then that's successful quite quickly.

A

Exit um go returns back to kelly, ruby that the post receive hook was successful. We exit our many processes and threads. We wake up the ruby worker yet again, and now we should be basically done: uh okay, yeah, let's, let's go down to that.

A

Yeah all right, so we wake up, and then we write out to the review uh one socket again back to the main gitly process that we're done, and I guess this is our new rough here. Okay.

A

So if we look at.

A

A

Okay, so write that out, let's just come back.

A

Here the main guilty process reads: it.

A

Then down here we write it out over tcp and we oh we're still sending post receive hook there are we gonna get the user commit file again somewhere in here? Oh right yeah, so we still need to do the cache again. Okay. So at this point we've done our mutation to the the repository.

A

Now we need to update our cache. So that's what's going to happen here is that we go in and create the new rest file um right to it, and then we log the updated cache successfully and then here we log, the actual user commits file itself was also done and took a little over a second, that's with us trace, running and sell everything down.

A

And then we log something more about the disk cache, but okay yeah, so that that has user commit files. That's one of the most complex rpgs. We have um just to recap so to get italy, then the gitly ruby gives the ruby then goes to gitly again several times. Then it allows the repo itself internally. Then it launches previously folks it's going to go back to gitaly, which then go out to the rails application.

A

Let's come back to get the ruby, then we'll do the update, and then we do the post receive hooks, and then we go out to rails again, yeah, so we're just all over the place and any any at any point. If any of those connections break, the entire thing falls over. um So that is something to be aware of okay, so that is gettingly in asteroids um all right. Hopefully, this was useful and interesting. Thanks for watching take it easy.