RX 24 - Elevate Your Church's Cybersecurity

Transcribed Content

Hi. Welcome, everybody. Next session is look what you've done, how to observe your code performance. And Nick Erdo is gonna be presenting here. Let's give him a big round of applause. Sorry. Technical difficulties with the mic. Be right back with you. Testing. Oh, okay. Well, as much as I like the other thing, I don't like hearing my voice echoing. All right, take two. Ready? All right, so for those of you that are not developers, you might be bored. So I'm kind of going to walk you through some Visual Studio stuff that we do, and how we check for some of the performance issues that we have in the code. And so I was going to ask how long the C developers have been developing, but there's not many of you. All right, so we usually show this pyramid. It's kind of an older pyramid that we used to use early on in the early days. And it was like the C was at the bottom and the HTML was at the top. And it said, if you know some HTML, CSS, you know you can do some things in Rock. And the deeper you got, the more you could do. Which is true, but in terms of the audience here today, I recognize that there's not many C developers, which is my target audience for this. All right. So here are a few ways, and I would say there's four primary ways, to see what's happening on your rock system. So the first one is the exception log. Now how many of you have looked into the exception log, by show of hands? Okay, everybody. One of the issues with exception logging is it's kind of like a noisy place. It's kind of a dumping grounds and it was never really intended to be the place for you to log things. It's really a place for you to write exceptions that happened so an admin could go and look and say, oh, okay, I see there's a problem over here on this page. Something's misconfigured or broken. But it's kind of not quite like that. So we're guilty of putting too much in there. And I don't want to talk too much about it since it's not really encouraged to write exceptions. Those should just be bugs and problems. If any of you have looked in there, you've probably seen lava, a lot of lava exceptions. When people are writing lava, if they form their lava incorrectly, it'll write an exception in there. Again, kind of noisy. The next spot, which isn't that many years old, we started was the rock logs. How many of you have been into the area where rock logs are? Show of hands. Okay, that's more than I thought. That's very good. So that's really the appropriate place to write logging. And then there is something else that we would call SQL logging. Now that's sort of a trick thing. It's really a trick that you use when you're developing. So how many know that there's a method on the rock context called SQL logging and you could pass a true in there? Okay, I know you know. Okay, good. Yeah. So if you are a C developer, you can turn logging on in there and we're going to talk about that. I'm going to show you some examples. And then last but not least is the observability stuff that we've added into Rock. It's new in version 16. And how many of you have an observability server? Or a service that you should subscribe to? Okay. Now I'm not going to show the New Relic one. We're just, in fact my screenshots are all from something, a local tool that you can run on your workstation. Okay, so I think I already kind of covered this. Why should you use the exception log? It really is just for exceptions. So if something goes horribly wrong, that exception would get caught by rock and logged there. If you have code that is writing to the exception log hoping that an admin is going to go look at it to read something that you're trying to tell them about configuration error, that's probably Okay. But if you're just trying to log, like debug type information, that's not the best place we would say don't do that. Yeah, its purpose was to communicate those problems to the administrator. Okay. I think I covered all that in my words. Some problems are really hard to track down by looking exception log. You're often scratching your head saying, I have no idea where that came from. We have experienced the same thing. So it's not just something you're doing wrong. It's kind of the way it is. All right. So the logging engine, what I would call level one diagnostics and troubleshooting, this is changing in version 17. I don't like change for change sake, but I was assured by our team that it had to happen. We had to make these changes. So most of the examples you'll see in the slides I believe are version 16 examples. But we're going to talk about, I'm going to show you the difference between v16 and v17 shortly here. So why would you use the logger? Well, the logger is great to use when you're, again, trying to communicate details, maybe not to the administrator like I wrote in my notes here. It's really more for, I would say, troubleshooting issues. Please. Next slide. We have often turned on logging at certain levels on production systems to try and track down problems. This is the way we had to do it prior to observability. So we would maybe ship that person a DLL with some additional logging in there to try and like pinpoint, okay, we'll put some logs here, put some logs here in the code. It's really quite crude. You feel like a caveman when you're doing this. We'll give the church partner a DLL. They'll run it. The problem will happen. We'll go look in these logs to see, Okay, why did it take so long between here and here? We're going to show an example of that. There are six log levels in logging. There's fatal, error, warning, info, debug, and then all. If you set your debug log level, and there's a screen in Rock coming up, I'll show you that too, to fatal, well then you're only going to see log messages that were written with the category or tag of fatal. If you say all, you're going to just see everything. All kinds of things that have debug logging and info logging are going to start pouring out to that log file. V17, just slight differences here. Critical, error, warning, information, debug, and trace. Now logging isn't free. But it's pretty fast. But it's not free. So it does take about eight microseconds to log something. So if you don't have to log, don't log. We don't want to just start peppering logging statements throughout the code base Because they do take a little bit of a hit to check, do I need to log something? If not, then it skips over it. If you are logging then you have to write, ROCK has to write to a log file. And that's a physical log file, I should add that. If you're in a multi host environment where you have like a farm of rock instances, just realize like that's the log written on one rock instance. So you might need to make sure you're targeting one particular instance in your farm. So I like to say don't abuse logging. And then again, show of hands, is this somewhat familiar to people who have been in Rock to set up logging? What you'll see here is these are domains you could pick in version 16. So at the top there you'll see what logging level do you want to log, and then domains. Then how big of a file size do you want to allow, and how many backups of those files. So it'll generate 20, in this case 20 megabytes. It'll move that over, it'll start writing another 20 megs and it'll basically, you'll have 20 times 20 megabytes of data total. In this case we'll tell you there if your math is bad, 400 megabytes will be on your server's file system. In v17, it's a little different. So you pick the radio buttons at the top there, what level or verbosity level. And then, I'm sorry it's all washed out, you can't quite see it, but that should be a dropdown list there. And those categories to log would look something like this. So we've decorated a bunch of classes in Rock So you can get a little bit more granular control about what's going to log. So you won't get so much noise. You can just pick one particular, very specific thing. Just wanted to see when rock. Bus. Message. Creditcards is expiring message happens, you can get those log entries. So pretty granular, but it's not perfect. And there is a section in the three zero three guide that has some additional details on what you need to do if you want to decorate your own code so it shows up in that dropdown list. And then there's some other situations where if you look down at the bottom there it says advanced configuration. In the previous screen there's a spot where you could put that little JSON snippet, and you could, you don't have to decorate your code, you just configure it this way. Okay. So what's the difference between v 16 and v 17? Not too big of a difference, but as you can see there, it used to be rocklogger.log followed by what level. So if it was an informational message, information. If it was an error, dot error, etcetera. In v 17, it's logger.log information. So pretty similar. Same thing. Replace the word log in log information with whatever level you want. There may be another method signature for this where you could like pass in the log level and call a more generic logger. But I wanted to show you this one because it's just more comparable. So now I'm going to kind of take a look at an example from a rock job. So I'm going to pick on this one particular job for the rest of the session pretty much. Are any of you familiar with the group leader pending notifications rock job? It's basically a job that will send out to the group leaders all the people that are pending in their group. So one day about two months ago, I was troubleshooting a problem and I'm like, Okay, this is going to be my material for Rx. So I started doing some logging just to see what would happen here and try and get to the bottom of this problem. So here we're near the top of the main execute method on a rock job. And we've added that debugger log line before, really before anything significant happens. So then at the bottom of the code, rock logger, log debug, I say done. So really all we're doing is here, we're just putting an entry, like a timestamp in the log, when it started and when it finished. Again, very crude. So I run the job and then out comes an email. I'm like, Okay, there it is. I set up my test data. So I got Brian got an email that Corey Stone and Nancy Turner are pending in their group. So one email. I look at the log and you could see it's old to new. And I'm like why? Six seconds. Why did it take six seconds? So you could see start querying at four forty eight, eleven seconds, and four forty eight, seventeen seconds, it was done. So I'm like, Okay, now what? What do you do at that point? You add more logs. When you're doing rock logging that's what you got. You just add more logging, which isn't great. So let's move on to the next level. Because again, that's pretty crude. That technique is good, only good for like getting you into a particular area. But again, it's all, I'd say, superseded by the observability power that you will now have in version 16 and beyond. So now we're going to talk about the Rock context SQL logging. So back into our job and here, right after I create that Rock context on line 67, I'm saying, Okay, Rock context, SQL logging true. And that's going to enable some things inside of Rock. And then just because I'm in the habit of doing this, I always end my logging. Now in this case that was all the context did. So you don't really have to turn logging off, but it's to me a good practice to turn off your logging. In some other situations, you've got like a rock context and you're doing something, doing something, doing something, and you're like, well I don't want to, I don't care about what happens after that. So it's really relevant to turn the SQL logging off. But what does this do? Like what happens as a result of that? Well, when you run it, now this is me running this in Visual Studio. If you go down to your output window there, let's zoom into that. That's impossible to read. That's still pretty difficult for you guys in the back. I warned you. What you're going to see here is every query that that raw context handled so when we write queries in code, it's link, L I N Q, that link turns into SQL. And this logs what got run. So you're going to see it declared a variable up there, a unique identifier. You could literally take everything between the begin and the end and run that code also in SQL Server Management Studio or elsewhere. It's a really handy tool. And this is what we've been using for years to kind of troubleshoot problems. But you can see here there was only, well this one call I should say, this one particular call took twelve point zero milliseconds. So nothing to see there. That will keep, it'll basically spit out all of these calls. So you get this list, call 1, call 2, call 3, and I chopped out the SQL that's in between there because you don't want to see all the SQL. And at the very end it'll even give you the total time. So call 10 timings. There were 10 SQL calls, took a total of eighty one milliseconds, which isn't bad at all. I mean it's not fantastic but it's not the end of the world. So what do you conclude? Well you might conclude that the delay, that six second delay has nothing to do with the link queries. If you run this enough times over and over, might, you know, that might be true. And often it can be true. Now, if you saw something like that, which is six thousand seven hundred and ninety one milliseconds, well then that's six seconds. Then you can panic. You could say, Okay, here it is, smoking gun, let's go dig in. Let's figure out what in the world, why one of those queries took that long. Because generally speaking, the queries you write in your code, they should be like milliseconds. If they're taking seconds and it's in your code, there's probably an optimization step that you wanna take a look at. Okay. So last section, observability, level three. I would call this like longer term logging, longer term diagnostics. And it's good to probably use in spots where you haven't maybe even checked the optimization in your code. So we've started wrapping chunks of rock code at a high level. So those things will just start logging to observability, which I'm going to show you soon. I promise. But what is observability? Well, the definition here is the observability is the ability to understand the internal state of a system by examining its outputs. Okay. Being able to understand the internal state by examining its telemetry data, which includes traces, metrics, and logs. These are like the standard definitions you'll get from observability tools. And ROCK, just FYI, ROCK implements what's called an open telemetry standard. So we don't just do New Relic. It's open telemetry. So a variety of tools, observability tools will work. As long as they support open telemetry, then you're good. So what is OpenTelemetry? Well, it's an observability framework designed to create and manage telemetry data such as traces, metrics, and logs. Felt like somewhat circular logic a little bit, but there's a nuance in there. I just wanted to make sure you guys understood. OpenTelemetry is supposed to be vendor and tool agnostic. Thank you. All right. So for the rest of the session here, I think you're going to see some slides using Jaeger. Has anyone ever heard of Jaeger or used Jaeger? Okay. At the very end, the very last slide is a slide that gives you a little bit of how we run Jaeger. I don't walk you through installing Jaeger. It's a free executable. You can download it. You run it. It'll run on a port. You point your rock to it. I'll show you that part. So it does all require though that you go into your system settings under system configuration and you check that little checkbox, enable observability. That's kind of step one. The next part is your endpoint. And that's something that will basically is determined by whatever observability engine you're using. So in my case, I'm just pointing to a local Jaeger install. So I have started up Jaeger at this point and it's running and I give it that endpoint and then you need to select the right endpoint protocol. In Jaeger's case it's HTTP Protobuf. I think that was all we had to do. Oh, I think I have a yeah, and there's a link. Yeah, Okay. Yeah, that link down there at the bottom is the same. So if you saw Michael Garrison's session, he walked you through at a way more detailed level of how do you just use observability. But what I'm doing is I'm using observability like a laser focusing in on just one particular job. So if you have questions about just observability in general, I guess see me tonight and I'll fire it up and we could look at it on my laptop. And I'll walk you through like live examples. But I dare not try to run that live during this forty minute session. Okay. So here we are looking at a trace from the operation there. That first arrow up there is telling you which job, and this is kind of standard rock notation. We've decorated jobs with the word job followed by the job name. So I selected that particular operation from the dropdown list, and now I'm looking at just this one job. And you can see there's there's the execution of it there. And at the very end let's see. Do I have that highlighted? Okay. It's almost impossible to read. 78 spans. So what are spans? Well spans are sort of, and this is my terminology, it's the little chunks of code that ran or SQL that are running, that are taking time on your server. So let's just look at an example of those 76 spans. What you'll see when you drill into that is a waterfall chart. And at the very top you see that one that goes all the way across, that's the parent. And it's just going to show you that took three seconds to run. So in this particular run it didn't take well yeah, the job didn't take six seconds. It only took about three seconds here. And then all the child spans. And that's really where the fun begins. So you start looking at these spans and you know, eyes glaze over the first time you see it. It's very Greek looking. You're like, Okay, what, where do I start? What I would say is just start looking for patterns. So if you if you spent some time up there, you would see that there are a bunch of selects on group members, on phone number, on location. And then there's a couple like on system communication. And you'll see these like over and over. And that's kind of a clue like, why did it fetch the system communication multiple times? So you kind of start to play sleuth at this point. So let's click into one of those. So we click into it. We expand it. If you expand the tags in the process, you'll see a little bit more data. But what I want to focus in on at this point is that little hash up there, the number hash. It's like 3102525604. You grab that from the select. This is the one we want to look at. We want to figure out where is that coming from. So I went and grabbed it. And you could see there that same query is highlighted. I just highlighted them. That's how many times it happened. So I'm going to take that query and I'm going to go put it into Rock inside of the targeted queries. So back where you configured observability, this is that same screen. You just add that hash in there. And what happens is now Rock's going to send some more data to observability. Because by default you don't want to send all this extra data. You'd just clog your network with a lot of junk. So now I run the job again, come back to that same particular hash, query hash up there. And now I can see the SQL that was run. So that's cool. Get more data. I don't think it's on this screen, but if I scroll down and look under the tags there is a rockdb dot stack trace. Yes. I can see the line number where all these things are happening. And I'm I'm confused. I'm I'm saying why? This this isn't my code? I don't see the job in there. What happened? So now my brain is like trying to figure out, okay, what's happening here? I see dot liquid. Dot liquid. And then I see at the bottom, render all. And I'm like, oh, the template. This job sends an email template and that email template isn't using my rock context. Right? The rock context that we were looking at earlier, it fired up and used its own rock context, potentially. I mean these are the things that you start thinking about. So that led me to want to go look at the template. So my journey takes us over to now the template that was tied to that job. So now this is the email, the communication template that gets sent out by that job. And what are we what are we looking for? What are we noticing? I don't know if you can see that. Again, apologize. That says pending individuals dot phone numbers. I'm like, okay, well, pending individuals, that was like what the job did. The job went and fetched the pending individuals. But in order to get the pending individuals, those are group members. So now we're but we need the phone numbers. So we've got to go from a group member to a person to phone numbers. Okay, so that's one thing. You're like, oh, I know. It probably had to go fetch that data after my query, something we call lazy loading. So it ran the query to get group members but then it was going through looping through each member and had to fetch their phone number. So it made another query to go get phone number data. Also, whoops. Also, hard to read, highlighted up there in pink, there's a lava filter being used called address home. Well, there's nothing you could do with that. Like the fact that it's piping the pending individual into a LAVA filter called address, that's that's out of your control now. There's nothing the job can do to fix that problem. Whenever you're using Lava, there's a possibility or potential that you're fetching more data. And there's really nothing you could do about that. So you say, Okay, fine. I surrender on address. But what can we do about phone numbers? Well, if we just go into that job and change that query and add group.members.person dot phone numbers, lo and behold, now it doesn't have to fetch that data. And so that eliminated a handful of SQL calls. So in this particular run it reduced the number of queries by 18. So I went from 78 spans to whatever, minus 18. So I counted that as a win. But down the rabbit hole you go because now you're like, Okay, what else can I find? And you then discover another thing that the job is re fetching the whole system communication from the database unnecessarily simply because instead of passing the entire do I have a screenshot of that? Yeah, instead of passing the entire system communication which we had previously fetched, we just passed the GUID. And unbeknownst to the developer who wrote this, he didn't realize like if you pass only the GUID then that method later on has to go re fetch the whole system communication. So I already had it. Just get rid of the dot GUID and pass the whole thing. Thankfully there was a method signature that took both and that solved that problem. So now there goes a couple more queries. Two hours later. So you just keep doing this, right? You're like, all right, what else can I find? And it's either fun or it's tedious. Hopefully it's fun. I had fun that night. It was about two hours. And let me zoom in on that. I think I got it down to really what you're seeing here are the ones that were in the job that the job could control. The other things you basically have to conclude through some analysis of like, well where are all these other queries coming from? Part of the two hours later. You conclude that two of the queries per there are going to be two queries per pending group member. And part of that's because there's a pre and post save operation that'll happen every time you like touch a group member. And in this particular case, it was changing the group member's flag to notified that they had been notified or the leader had been notified. Yeah, it was changing there is notified bit to true. And so in this particular case that was a total of 33 of the 35 calls were kind of beyond my control. Because Rock's internal engine is doing things that the job isn't doing. And I'm using this, again, I'm using the job as an example of like your own code. There's just gonna be some things that are beyond your control and it's part of the power of Rock. Rock can do some powerful things but it comes at a cost because it will have to Sometimes