What are the fields in slow queries log?

I would like to know what the different elements in the slow queries log file represent. I think I've figure out most but I don't know where to look it up since it doesn't seem to be part of any config I could find.

Any suggestions?

I figured the following...

2016-11-21 09:08:49,068
http-nio-8080-exec-16 INFO username 548x103721x5 11nnyad /url/ [issue.search.providers.LuceneSearchProvider_SLOW] JQL query '{filter in ("Release actual ")} ' produced lucene query redacted_query' and took '561' ms to run.


Timestamp thread? type? Username log_id ??? url query_info query duration

1 answer

1 accepted

1 vote
Accepted answer
Chris Fuller Atlassian Team Nov 30, 2016

Basics

  • 2016-11-21 09:08:49,068 – Timestamp

  • http-nio-8080-exec-16 – Thread
  • INFO – Log level
  • username – Well, yes
  • 548x103721x5jira.request.id (see below)
  • 11nnyad – jira.request.assession.id (see below)
  • /url/ – Well, yes
  • [issue.search.providers.LuceneSearchProvider_SLOW] – logger name
  • Next comes the log message with the fields:
    • '{filter in ("Release actual ")}' – the JQL
    • redacted_query – the resulting Lucene search expression (warning: may contain binary data if that's the form that the data takes in the index)
    • '561' ms – how long it took (we log anything over 400ms by default)
 

About jira.request.id

This is meant to be a unique identifier for each HTTP request so you can filter by it to group together all the log messages that are tied to it.  You could just treat it as an opaque string, but if you're curious, it consists of 3 numbers with the following meaning:
  • The first number (548) is roughly the time of day, in minutes since midnight.  Internal comments in the code still match the ancient versions of JIRA (prior to 4.1) when it was seconds since midnight so could be as large as 86400 or so, but since JIRA 4.1 it should stay under 1440.
  • The second number (103721) is a cumulative request counter.  It increments with every request and should therefore guarantee that the overall request ID is always unique (the other fields are there to give other information).  Well, except that this counter resets if you restart JIRA. This is part of why the first number, giving time of day, is also included.
  • The third number (5) is the number of concurrent HTTP requests that were being processed at the time the ID was generated (it is not updated if the count changes within the request, but offers some idea of how busy the system might have been at the time, which sometimes matters).

About jira.request.assession.id

This is the HTTP session ID, but hashed so that it cannot be abused to steal a user's session and impersonate them.  The intent is that if a user is complaining that something is wrong and you can get them to tell you the value of the ASESSIONID cookie that their browser has for that JIRA instance, this gives you a way to correlate that specific session's activity instead of all activity for that user.  This would be particularly important when trying to troubleshoot something that happens to the user in one login session but not on another machine or has correctly entered their password but still gets sent back to the login page for some reason.

 

Thanks for this detailed answer. I really appreciate it.

In case anybody finds this. I was playing with Splunk and it seems that not all elements are present for every line in the log so watch out for that...

Chris Fuller Atlassian Team Dec 01, 2016

See what I said about "redacted_query" above.

warning: may contain binary data if that's the form that the data takes in the index

These are the raw binary values that are stored for these fields in the index, and they are very likely to confuse the character encoding for something like JSON or XML.  I'm not overly familiar with Splunk, but I'm given to understand that it uses JSON as its transport.  It will expect the log message to be well-formed UTF-8, and it isn't.

 

That wasn't the part that was messing with the extraction. There was a string I could use to identify the end of the Leucene search expression. I can't seem to access the regexp that I was using to extract the data from Splunk, which sucks...

Chris Fuller Atlassian Team Dec 01, 2016

Oh, sorry; I misread your earlier comment as saying you were missing whole lines from Splunk and thought encoding might be the issue, but you're saying that the problem is that individual fields themselves can be missing?

For some of these, I don't find that very surprising, particularly because searches can sometimes be run by background processes rather than by specific user interface activity.  For example, if the search is run by a filter subscription, then the user would be present, but no value would make sense for jira.request.assession.id because the query isn't being run from the user interface.  Some of the fields will substitute a - character for the value when there is nothing useful to report, but that probably isn't true of all of them, especially the custom fields that we add to the logs ourselves.  If you are very specific that exactly one space separates those fields, that may be enough to get you there.

 

Suggest an answer

Log in or Sign up to answer
Community showcase
Posted 5 hours ago in Jira Service Desk

Looking for anyone who has switched from Zendesk to Jira Service Desk

Hi Community! The Jira Service Desk marketing team is looking for customers who have successfully switched from Zendesk to Jira Service Desk!   We’d love to hear your thoughts on the pros and ...

11 views 0 1
Join discussion

Atlassian User Groups

Connect with like-minded Atlassian users at free events near you!

Find a group

Connect with like-minded Atlassian users at free events near you!

Find my local user group

Unfortunately there are no AUG chapters near you at the moment.

Start an AUG

You're one step closer to meeting fellow Atlassian users at your local meet up. Learn more about AUGs

Groups near you