Tag: Logging

So, we’ve discussed how to read your logs, and what impact changing them will have on your disk drives. So how do we go about changing logging levels and tuning logging? That is what we are going to discuss today. So without much preamble, lets get into this.

Should I adjust my logging levels?

If I’m being honest, No. Well, that was a quick blog post, I’ll see you next week!

Actually, let me explain. The default levels are sufficient for 99% of admins out there. It’s a good balance of what you need to know to diagnose issues without filling up your disks. Typically, I only recommend people only adjust these levels if asked to do so by Atlassian or App Vendor support.

However, it’s still important that you know how to do so when asked. And with a bit of homework you might even be able to adjust them and find your answers before you have to get support involved. My advice though is to do so carefully if you choose to.

I just need to note something here, and it’s something I forgot to mention last week. Debug level logs can sometimes capture passwords in the log file. I should not have to tell you why that could be bad. However, this is just one more reason why you should really think twice about capturing any logs on the Debug level.

Temporary vs Permanent

So, the first question you need to answer is do you need this change to be permanent or temporary. Atlassian does give us two ways to change logging – one via the Admin console in the web UI, which will only last until your next JIRA restart. As such I label this the “temporary” option. The second option is by changing some files within the JIRA install directory, which will persist across application restarts, and as such I label a “permanent” change.

As I tend to recommend you stick to defaults, so without any deeper context, temporary is my go to answer. However, as with all things Atlassian, context is everything. Lets say you’ve had some problems with a new app you’ve installed onto your instance, and it’s causing the Application to restart regularly. This is a time you’d want to look at a more permanent solution, as you’re not going to capture those detailed logs while JIRA loads up otherwise.

If you are working with Support, they will almost always tell you to go the temporary route. However, no matter what I say, my advice is to follow their advice. Seriously, they are scary good at what they do, and they are not going to steer you wrong.

Making a Temporary change to logging.

To change something temporarily within the logs, we’ll need to go to the Logging and Profiling section of the JIRA Administration Console. Once there, you’ll find it under System -> Logging and Profiling.

Note: You will need System Administrator global permissions to be able to see this section.

As a pro-tip, you can also find any admin page from anywhere in JIRA by hitting the period key on your keyboard, then typing the page you are interested in. For this to work, your cursor must be outside a text input box of any kind.

Once here, you’ll see different sections:

• Mark Logs
• HTTP Access Logging
• SQL Logging
• Profiling
• Mail
• Default Loggers

Today we’re going to be primarily interested in the Mark Logs section and the Default Loggers section. Everything else is available to turn on, but remember that these logs will only run until the next time you restart JIRA.

Mark Logs

The first section here is where you can add a comment into your logs. You can also roll over your logs. A roll over is where JIRA will increment the end number on all existing rolled over logs, copy the current log file to atlassian-jira.log.1, then start a new atlassian-jira.log file.

Both of these techniques are great for trying to mark a section of logs before doing some operation or test. In fact, I made great use of this functionality to do my testing last week on log sizes. I can search a ten minute manual search for where you started doing something to a “It’s right here” instant search.

Default Loggers

The next section of interest is the Default Loggers section. This has the familiar logging levels shown, on a per-package bases. A package is an individual class or object within the JAVA code, so each of these will adjust the logging on a specific aspect for JIRA.

This unfortunately is an exhaustive list, and I don’t have time to write up what each of them do (assuming I even know that!). However, most of these come down to logic, and with a bit of searching you can find something.

That is to say I won’t offer any guidance. If I’m being honest, it’s amazing how many times JIRA problems turn out to be App problems. So I’m going to quickly discuss how to add and adjust logs for an App here.

Our first step is to go to our App Manager, then expand the information for the App we are interested in.

Look for the App Key, highlighted above, and copy it. Then head over to Logging and Profiling, and under Default Loggers, click “Configure logging level for another package”. Past the App key into the Package name section, then select your logging level. Click Add and boom, you are now logging for that particular App.

Permanent Logging Changes

To change logging levels, you will need to find the <jira-install-dir>/atlassian-jira/WEB-INF/classes/log4j.properties.

Here we can change a number of things, including log levels of various packages, where the logs are, and so on.

Super Important Note: Before making any changes to this file. Make a copy and save it in a safe place. Your future self will thank you.

To change the logging level, you first need to know the package you are adjusting for. You will either have gotten this from Support or the App Manager section of JIRA. Then we’ll look for log4j.logger.<package-name>. You should see something like this:

log4j.logger.com.atlassian = WARN, console, filelog
log4j.additivity.com.atlassian = false

To adjust the log level, change “WARN” to any of the other logging levels, then save. After you restart JIRA you should see the logging level change reflected. This goes with any change to this log file – you will need to restart JIRA to see any changes.

And that’s logging, done.

So I’ve actually had a lot of fun going back over this subject matter. It was also the first reader-requested topic, so that is amazing in and off itself. So what do you guys think I should cover next? Leave a comment here or on LinkedIn and if it’s good, I’ll cover it. So until next time, this is Rodney, asking “Have you updated your JIRA Issues today?”

Well, seems we are back on track. Last time we looked at logging, we went over how to decode the information that was in the logs. During that piece, I made the following claim:

If you set everything to Debug before you leave on Friday, by the time you are sitting down for dinner on Saturday, you’re going to be paged for a full disk.

Following the Breadcrumbs: Decoding JIRA’s Logs, 30 Oct, 2019

Well, this got me to thinking….exactly how much does JIRA’s logging level impact log size. To figure this out, we need a bit of SCIENCE!

Ze Experiment!

So here’s what I’m thinking. We take a normal JIRA instance, and we do a set number of tasks in there, roll over the logs, then see what size they are. Rinse and Repeat per log level.

So the list of tasks I have for each iteration is:

• Roll Over the Logs
• Logout
• Log in
• Create Issue
• Comment on Issue
• Close Issue
• Search for closed issue
• Log into the Admin Console
• Run Directory Sync
• Roll Logs

Between the last Roll over and the first one of the next iteration is when I’ll capture log size and adjust the logging levels.

Now to have as much of an apples to apples comparison, I’ll need to limit the background tasks as much as possible. The biggest one I can think of is the automated directory sync, which will need to be disabled for the test. However, as this is a regular activity within JIRA, I’ll be including a manual directory sync to capture that into the data set.

I’ll also need a control to measure what JIRA does by default, but that will be my first run. To make sure I can return to defaults later, I’ll be adjusting the logging levels in Administration -> System -> Logging and Profiling. Changes to the logging level here do not persist over a restart, so this should be ideal. So, without further adieu, See you on the other side.

The Results

Well, That was an adventure. I ended up taking a backup of the log4j.properties file and changing it. Turns out changing > 110 settings by hand one at a time is not very time-efficient. Changing the log4j.properties file dropped the number that I had to change manually to ~30.

I tried to be as consistent as possible with each run. That means I had the same entries for each field on the issue I created, same comment, same click path, etc. I even goofed up my search on the control run (typed issueky instead of issuekey), and I repeated that mistake for each run afterwards.

Another note I want to make is that there was one setting I could not change. Turns out that if the com.atlassian.jira.util.log.LogMarker object is anything but Info, JIRA will crash when you go to roll over the logs. Oops!

Conclusions

I think even considering all that, my assertion still stands. This was one person doing somewhat normal JIRA tasks. With that the Debug was still almost 1000x the Info log. Fun fact, it rolled over the logs automatically four times. Now multiply that by how many people are using your instance, and how many times they will be doing these kinds of operations, over and over again. Even if they aren’t, there are automated processes like the Directory syncs that will take up log space. It will definitely add up fast.

However, I think the bigger consideration here is never take anything at face value. Yeah, I’m an expert, but even I was just parroting something I had been told about logging. Now I have the experiment and data to backup my assertion. Don’t be afraid to put things to a test. You might discover where some advice isn’t right for your environment. Or you might find out why things were said, and become that much more knowledgeable . The point is to always be learning.

So until next week, this is Rodney, asking “Have you updated your JIRA issues today?”

Well, that’s a thing. For those that don’t know, Rachel pretty much wrote the book on being a JIRA Admin. So, I guess it’s time to put up or shut up. JIRA Logging, lets do this.

For those of us in the trenches, logs are life savers. No, really. When something goes wrong within an application, logs often are our first, and sometimes only view into why it went wrong. You can tell a lot about what JIRA is doing from it’s logs – If you know what to look for.

As always, we start any look into a new aspect of JIRA by looking at the documentation. Here, we find the relevant document under Logging and Profiling:

• Logging and profiling – Atlassian Documentation

Where to find your logs.

Finding your logs is actually pretty simple, assuming you know where your home directory is. Your log files for JIRA can be found at <jira_home_directory>/log/.

Navigating here, you will see several log files, usually along the lines of “atlassian-jira-<name>.log. If that log has had a roll-over, you will see some repeats of them, with older ones being followed by a number.

The one we will be interested in nine times out of ten is the atlassian-jira.log file.

But what about the Catalina.out file?

You my have noticed another log file in the JIRA install directory called catalina.out. This is tomcat’s log file, and while it replicates most of what is in atlassian-jira.log, it won’t have everything JIRA’s doing in there. Furthermore, it will muddy the water with additional information from Tomcat. If you haven’t changed any settings in the JIRA install directory, you won’t have a lot of reasons to go into there.

However, I have found catalina.out helpful when I’ve had an issue starting JIRA because the JVM environment was misconfigured. In that case, JIRA’s logs will have nothing, but Tomcat will report the Java error. If your JIRA is up and running though, don’t worry about this log.

Typical Logs

So, here is a snapshot of the logs after doing some typical things within JIRA:

Yeah, you may have to zoom in a bit there. But for the whole, looks like organized chaos. And well, it is. And in a live production environment, these may be zooming by so fast you may not have a chance to actually absorb what’s happening. With a bit of practice you can get to a point where you can watch the logs stream by and see only the things that look out of the ordinary…but even that’s not perfect. However, lets look at one entry, when I access the login page for JIRA.

2019-10-29 08:08:44,423 http-nio-8080-exec-23 INFO anonymous 488x35978x1 xmd6sf 192.168.<redacted>,192.168.<redacted> /rest/gadget/1.0/login [c.a.jira.index.MonitoringIndexWriter] [lucene-stats] flush stats: snapshotCount=6, totalCount=63, periodSec=486768, flushIntervalMillis=81128149, indexDirectory=null, indexWriterId=com.atlassian.jira.index.MonitoringIndexWriter@19cc4430, indexDirectoryId=RAMDirectory@5d7db2f9 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@14d78abf

So, what do we have going on here. At first glance, we notice several parts.

Time Stamp and Misc Information

First, we have the time stamp. This is often the best thing to filter off of. If you know when an event you are interested in happened, you can start around that time and work your way backwards. It can narrow hundreds of thousands of lines to maybe a few hundred.

The next bit is just an identifier that tells you what part of JIRA is generating the log. for the above entry, it’s the web server. It may take some digging to figure out what is a part of what and honestly unless you are doing log aggregation, it likely isn’t going to help you a whole lot.

Logging Level

The third bit – that’s interesting. It’s the logging level. Logging levels tell the application how much of what’s going on you want recorded, and come in five levels:

You may notice I put them onto a scale. That is because as you change the logging level, you are increasing or decreasing how much of what is going on is recorded to the logs. I could do a whole post on logging levels alone, but the gist of it is if you set debug, you can almost watch all the variables change in real time in the logs. If you set it to Fatal, JIRA will only log entries when something catastrophic happens, and even then will likely leave out details leading up to the crash.

So this leads to the question: “If not enough information is a bad thing, why don’t we set everything to Debug and log all the things?”

If you haven’t guessed, there is a trade-off. Here, it’s disk space. If you set everything to Debug before you leave on Friday, by the time you are sitting down for dinner on Saturday, you’re going to be paged for a full disk. No really, you’ll be surprised how fast text can fill up a hard drive.

Speaking in general, you can also use Logging levels to tell if something bad is happening. The Developers will assign different events to different logging levels, based on their best guess on how important it is to log. That being said, I’ve seen items that were Warn or Error that were no big deal, and I’ve seen Info level log entries that were actually concerns. The easiest example I can think of is actually in my logs right now:

2019-10-29 08:30:11,656 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] Incremental synchronisation for directory [ 10000 ] was not completed, falling back to a full synchronisation
2019-10-29 08:30:11,656 Caesium-1-1 INFO ServiceRunner     [c.a.crowd.directory.DbCachingRemoteDirectory] INCREMENTAL synchronisation for directory [ 10000 ] was not successful, attempting FULL

This is a log level INFO, but it’s saying something causing it to fail an incremental synchronization from my LDAP Directory. In my test environment, the LDAP directory is small enough this won’t be a problem, but in a full corporate LDAP directory, this can cause a significant overhead. I’ve even DDoS’ed my own JIRA instance trying to do a full directory sync. And again, this is only a “INFO” level log…

Identifier

After the Log Level, we have the identifier information. For web traffic and actions, this will tell you whose account initiated the action that resulted in the log. If you have a problem that only one user is reporting, this can help as you can search the log for that username. Of if you want to know if that person did something that caused problems, there you go too.

For web traffic, this is also accompanied by a couple of IP Addresses, usually the user’s clientside IP Address, followed by the IP address of your proxy. This can be helpful for identifying traffic originating from outside your network, or investigating access that didn’t look right.

Package

After you have your identifier, you will see a section in a bracket. This is the package that generated the log. In lay mans terms, this is a more specific part of JIRA that generated the log. This can be a specific plugin (or part of a plugin), or a particular routine within JIRA. You can see the list of packages and their associated logging levels within the System -> Logging and Profiling section of the Administrative Control Panel in JIRA.

In speaking of Logging and Profiling, you can also change the logging level per package in this section as well. These changes will persist until the next time you restart JIRA. In a future post we’ll also cover how to change them permanently. You also have access to an even deeper logging level here called “Trace” – but it is recommend you only use that if you are asked to by Atlassian Support in order to help with a specific issue. Your disks will thank you.

Message

After all these details, we get to the meat of the log – the message. This is what happened, or didn’t happen, that warrants logging. This is the “What” to the rest of the logs “Who, When, and Where”. This is where you can dig in to find whatever problem you are looking for.

And that’s what’s in your JIRA Log

And that’s pretty much it. I do have one more thing for you. For me, reading white logs on a black background can make things easy to get mixed up. To help with this, I wrote up a quick little script that will look up where you JIRA Log is, and pass it through an Awk filter so that it will colorize things based off the log level for each entry. It will also follow the log, which means it will display entries in real time as they are updated into the logs, and keep doing so until you hit “Ctrl+C”.

For reference, the colors each log level will be:

• DEBUG: Green
• INFO: Default
• WARN: Yellow
• ERROR: Red
• FATAL: Magenta

#!/bin/bash
# Rodney Nissen
# Version 3
# Updated 10/29/2019
# Update JIRAINST to point to your JIRA Install Directory

JIRAINST="/opt/atlassian/jira"
JIRAHOME="$(sudo cat $JIRAINST/atlassian-jira/WEB-INF/classes/jira-application.properties | grep "jira.home = " | cut -d ' ' -f 3 | tr -d '\r')"
JIRALOG="$JIRAHOME/log/atlassian-jira.log"

sudo tail -f -n 50 $JIRALOG | awk '
  /DEBUG/ {print "\033[32m" $0 "\033[39m";next}
  /WARN/ {print "\033[033m" $0 "\033[39m";next}
  /ERROR/ {print "\033[31m" $0 "\033[39m";next}
  /FATAL/ {print "\033[35m" $0 "\033[39m";next}  
  1
'

I hope you will get as much use out of this tool as I have. As I stated in several parts of this post, I think this is the kind of subject that deserves a series of posts, not just one. As such, I’m thinking I’m going to do at least two more – one is an in depth dive into Logging Levels and what they actually mean, and another on how to play around with your logs. But until then, I’m Rodney, asking “Have you updated your JIRA Issues today?”