Log queries performed in kibana to the output log using a plugin

[pserrao]

I have been trying to log the query the user performs on the Kibana Discover tab into the stdout of the Kibana server.

I can see from the browser see that every time the user performs a search, a POST request is made to the "/elasticsearch/_msearch" containing the query, so I was trying to develop a plugin that hooks hapijs on the request and prints the POST payload to the kibana log:

On my plugin index.js (generated with yo), I added:

  server.on('response', function (request) {
    console.log('Request payload:', request.payload);
  }

Inside the init(server, options) section.
This successfully outputs the request being made, but I am unable to get the actual POST content

I also tried with:

server.ext('onPreHandler', function (request, reply) {
  server.log(['info'],request);
  return reply.continue();
}

But also without success.

Meanwhile I figured I can also see the query in the "spy tab" but from there I don't think its possible to log on the kibana server stdout from there...

Any hints on an approach to accomplish this? My final goal is to log both the user logged in kibana (w/ x-pack enabled) and the query he performed (any tips on how to get the username is also appreciated).

Thanks!

[LeeDr (Lee Drengenberg)]

Hi pserrao,

I think you want to use the Elasticsearch Slow Log feature;
https://www.elastic.co/guide/en/elasticsearch/reference/current/index-modules-slowlog.html

You can set the time to 0 and get it to log every query.
Then you could use something like logstash or filebeat to index those into Elasticsearch. Logstash might be best so you can filter only those messages.

Regards,
Lee

[pserrao]

Thanks for your reply,

I already explored that feature (Log the User and Query submited thru Kibana)

But unfortunately that feature doesn't log the username that performed the query, and I need to log both for audit purposes...

That is why I turned into Kibana since it seemed me that it would be possible to develop a plugin to log both (user and query) at the same time (or even feed it back to an elastic index like you suggested). Right now I'm trying to do the most simple thing, output to stdout with console.log() or server.log().

I was not able yet to print the POST content that I see being sent from the browser into the kibana server. I can hook in and dump the whole request variable, but the POST payload is not visible

I was also not able to print the username that is currently logged in kibana (it seems to me that the username string isn't being saved on the session variables on the kibana server side?)

I will also be required later on to add an input field that users need to fill in on the kibana interface whenever they perform a search, that piece of information they enter also needs to be logged in together with username and query. The final audit log doesn't have to be the whole json sent to elastic backend, it can be the multiple HTML parameters they entered/selected on the kibana discovery interface (i.e. query string + index name + timeframe + custom field I'll need to add), but as far as I can see the kibana server does not received those parameters isolated, it already receives the final elastic json in the POST (probably constructed on by the angular component on the browser) and it just proxies it to the elastic backend, so I'm also not sure how I can inject there my custom input field...

Sorry for the long post, any suggestions on the best approachs to accomplish my final goal are really appreciated

[tylersmalley]

I would recommend looking at the ClientLogger here: https://github.com/elastic/kibana/blob/master/src/core_plugins/elasticsearch/lib/client_logger.js#L16

Setting elasticsearch.logQueries: true while running in ```--verbose` mode will output queries, but you're right - it's missing the user.

[Joe_Fleming]

What's the value of request.payload when it logs? I'm a little rusty on how hapi works, but according to the request object docs, that sounds like what you'd want. However, looking lifecycle docs, it's not clear if that event actually passes any arguments to the handler. I would expect your onPreHandler code above to have a value request.payload value though.

As for getting the "user", how are you defining a "user"? Are you using X-Pack Security? If so, you can use that plugin in your plugin to parse the active user out of the request. If you've rolled your own user management, I'm guessing you're using tokens of some kind, and I'd expect the process to be similar; you could just pull that information from request.headers.

[pserrao]

@tsmalley I had already tried setting on kibana.cfg:

logging.verbose: true
elasticsearch.logQueries: true

But I can not see the query string, I do see JSON for internal operations... but no user query JSON.

ops   [15:11:53.389]  memory: 136.9MB uptime: 0:01:08 load: [3.44 3.01 2.83] delay: 0.215
log   [15:11:53.390] [debug][monitoring-ui] Received Monitoring event data
respons [15:11:53.964]  GET /ui/favicons/favicon.ico 304 2ms - 9.0B
respons [15:11:53.976]  POST /elasticsearch/_msearch 200 10ms - 9.0B
log   [15:11:54.097] [debug][plugin] Checking Elasticsearch version
log   [15:11:54.099] [debug][admin][elasticsearch][query] 200
HEAD /

log   [15:11:54.099] [debug][plugin] Checking Elasticsearch version
log   [15:11:54.100] [debug][admin][elasticsearch][query] 200
GET /_nodes?filter_path=nodes.*.version%2Cnodes.*.http.publish_address%2Cnodes.*.ip

log   [15:11:54.102] [debug][admin][elasticsearch][query] 200
GET /_nodes/_local?filter_path=nodes.*.settings.tribe

log   [15:11:54.103] [debug][admin][elasticsearch][query] 200
POST /_mget
{"docs":[{"_index":".kibana","_type":"config","_id":"5.4.0"}]}
 log   [15:11:54.105] [debug][admin][elasticsearch][query] 200
GET /_cluster/health/.kibana?timeout=5s

  log   [15:11:54.106] [debug][admin][elasticsearch][query] 200
POST /.kibana/config/_search
{"size":1000,"sort":[{"buildNum":{"order":"desc","unmapped_type":"string"}}]}
log   [15:11:54.187] [debug][esqueue][reporting][worker] j3d4pvpe05zg1c0b3d6dqwvy - querying for outstanding jobs
log   [15:11:54.189] [debug][admin][elasticsearch][query] 200
POST /.reporting-*/esqueue/_search?version=true
{"_source":{"excludes":["output.content"]},"query":{"constant_score":{"filter":{"bool":{"filter":{"term":{"jobtype":"printable_pdf"}},"should":[{"term":{"status":"pending"}},{"bool":{"filter":[{"term":{"status":"processing"}},{"range":{"process_expiration":{"lte":"2017-05-31T15:11:54.186Z"}}}]}}]}}}},"sort":[{"priority":{"order":"asc"}},{"created_at":{"order":"asc"}}],"size":10}
log   [15:11:54.189] [debug][esqueue][reporting][worker] j3d4pvpe05zg1c0b3d6dqwvy - 0 outstanding jobs returned
log   [15:11:56.160] [debug][admin][elasticsearch][query] 200
POST /.reporting-*/esqueue/_search
{"_source":{"excludes":["output.content"]},"sort":{"completed_at":"asc"},"size":10,"query":{"constant_score":{"filter":{"bool":{"must":[{"range":{"completed_at":{"gt":1494936654225,"format":"epoch_millis"}}},{"term":{"created_by":"elastic"}}]}}}}}
respons [15:11:56.162]  GET /api/reporting/jobs/list_completed_since?since=2017-05-16T12%3A10%3A54.225Z 200 7ms - 9.0B
log   [15:11:56.606] [debug][plugin] Checking Elasticsearch version
log   [15:11:56.610] [debug][admin][elasticsearch][query] 200

Am I missing something?

[pserrao]

@Joe_Fleming

This is the content of the request.payload:
https://pastebin.com/A0JYkWA3

This is with:

server.on('response', function (request) {
    console.log(request.info.remoteAddress + ': ' + request.method.toUpperCase() + ' ' + request.url.path + ' --> ' + request.response.statusCode);
    console.log('Request payload:', request.payload);
}

I had also tried with the onPreHandler before like you mentioned:

server.ext('onPreHandler', function (request, reply) {
       server.log(['info'],request.payload);
      return reply.continue();
 });

And I get:
https://pastebin.com/6T6jqUq0

Regarding the user, yes I am using X-Pack, but I haven't managed to figure out how to get the active user performing the request.

I tried looking at the source and end up with:

server.log(['info'],server.plugins.security.getUser(request));

But I don't think I figured it right, because all I get is:

Promise {
  _bitField: 0,
  _fulfillmentHandler0: undefined,
  _rejectionHandler0: undefined,
  _progressHandler0: undefined,
  _promise0: undefined,
  _receiver0: undefined,
  _settledValue: undefined }

[Joe_Fleming]

So it looks like onPreHandler does in fact get the request object, and the payload looks pretty much like I'd expect it to look. All our code, and all the examples I can find online, rely on reading specific values off of the payload, object. For example, something like request.payload.message. I think the payload object IncomingMessage might be a getter, so you can't just log the whole thing, you have to pull off specific values. Sadly, it doesn't look like any of the getter values is just the body object.

Note that the request object does have a raw value, which gives you access to the raw node request object. I think that's a plain object, and you could try logging that. Note that you'll likely have to run that through a body parser, logging it directly probably isn't useful.

This may not be the best solution, but I can't seem to find a better way to get that request body object as a plain object. I suspect there's a better way, but you're going to have to do some research.

---

getUser is async, and returns a promise (as you can see in the log), so you can't use the value directly, you need a .then handler.

server.plugins.security.getUser(request)
.then(user => server.log(['info'], `user is ${user.username}`));

// or, using async/await
const user = await server.plugins.security.getUser(request);
server.log(['info'], `user is ${user.username}`);

Also note that if security is ever disabled (manually, or maybe due to a license change), this is going to fail oddly, because server.plugins.security will be undefined. Maybe it's doesn't matter to you, but it's something to be aware of.

If it does matter to you, you can wrap it, like so:

import { get } from 'lodash';

function getUserFactory(server) {
  return function getUser(request) {
    // if security isn't available, securityGetUser becomes a noop function and returns undefined
    const securityGetUser = get(server.plugins, 'security.getUser', function () {});
    return Promise.resolve(securityGetUser(request));
  };
}