What are the fields in slow queries log?

[Seb Kouba]

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

[crf · Accepted solution]

Basics

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

• http-nio-8080-exec-16 – Thread
• INFO – Log level
• username – Well, yes
• 548x103721x5 – jira.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.

[Seb Kouba]

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...

[crf]

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.

[Seb Kouba]

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...

[crf]

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.