Filebeat Pipeline debug output Publish event

Leon21 · April 28, 2021, 2:18pm

Hi,

I'm struggling with an issue in ingest pipeline for Okta module that seems not working and I could not view events on either dashboards or in Discover panel via searching.

I enabled debug output of filebeat and it seems the event is published to ES as I see in debug logs.

2021-04-25T22:01:36.725Z        DEBUG   [add_cloud_metadata]    add_cloud_metadata/providers.go:128     add_cloud_metadata: starting to fetch metadata, timeout=3s
2021-04-25T22:01:36.895Z        DEBUG   [add_cloud_metadata]    add_cloud_metadata/providers.go:165     add_cloud_metadata: received disposition for azure after 169.973871ms. result=[provider:azure, error=failed to unmarshal azure JSON of '': EOF, metadata={}]
2021-04-25T22:01:36.906Z        DEBUG   [add_cloud_metadata]    add_cloud_metadata/providers.go:165     add_cloud_metadata: received disposition for gcp after 181.216557ms. result=[provider:gcp, error=failed to unmarshal gcp JSON of '': EOF, metadata={}]
2021-04-25T22:01:37.342Z        INFO    instance/beat.go:304    Setup Beat: filebeat; Version: 7.12.0
2021-04-25T22:01:37.342Z        DEBUG   [beat]  instance/beat.go:330    Initializing output plugins
2021-04-25T22:01:37.342Z        INFO    [index-management]      idxmgmt/std.go:184      Set output.elasticsearch.index to 'filebeat-7.12.0' as ILM is enabled.
2021-04-25T22:01:37.343Z        INFO    eslegclient/connection.go:99    elasticsearch url: https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443
2021-04-25T22:01:37.343Z        DEBUG   [publisher]     pipeline/consumer.go:148        start pipeline event consumer
2021-04-25T22:01:37.343Z        INFO    [publisher]     pipeline/module.go:113  Beat name: servername
2021-04-25T22:01:37.363Z        INFO    [monitoring]    log/log.go:117  Starting metrics logging every 30s
2021-04-25T22:01:37.363Z        INFO    instance/beat.go:468    filebeat start running.
2021-04-25T22:01:37.364Z        INFO    [registrar]     registrar/registrar.go:109      States Loaded from registrar: 0
2021-04-25T22:01:37.364Z        INFO    [crawler]       beater/crawler.go:71    Loading Inputs: 2
2021-04-25T22:01:37.364Z        DEBUG   [cfgfile]       cfgfile/reload.go:132   Checking module configs from: /root/temp-fb/filebeat/modules.d/*.yml
2021-04-25T22:01:37.365Z        DEBUG   [registrar]     registrar/registrar.go:140      Starting Registrar
2021-04-25T22:01:37.365Z        DEBUG   [cfgfile]       cfgfile/cfgfile.go:193  Load config from file: /root/temp-fb/filebeat/modules.d/okta.yml
2021-04-25T22:01:37.365Z        DEBUG   [cfgfile]       cfgfile/reload.go:146   Number of module configs found: 1
2021-04-25T22:01:37.368Z        INFO    [crawler]       beater/crawler.go:108   Loading and starting Inputs completed. Enabled inputs: 0
2021-04-25T22:01:37.368Z        INFO    cfgfile/reload.go:164   Config reloader started
2021-04-25T22:01:37.368Z        DEBUG   [cfgfile]       cfgfile/reload.go:194   Scan for new config files
2021-04-25T22:01:37.368Z        DEBUG   [cfgfile]       cfgfile/cfgfile.go:193  Load config from file: /root/temp-fb/filebeat/modules.d/okta.yml
2021-04-25T22:01:37.368Z        DEBUG   [cfgfile]       cfgfile/reload.go:213   Number of module configs found: 1
2021-04-25T22:01:37.368Z        DEBUG   [reload]        cfgfile/list.go:63      Starting reload procedure, current runners: 0
2021-04-25T22:01:37.368Z        DEBUG   [reload]        cfgfile/list.go:81      Start list: 1, Stop list: 0
2021-04-25T22:01:37.370Z        DEBUG   [processors]    processors/processor.go:120     Generated new processors: decode_json_fields=message, rename=[{From:message To:event.original}], add_fields={"ecs":{"version":"1.8.0"}}
2021-04-25T22:01:37.370Z        DEBUG   [reload]        cfgfile/list.go:105     Starting runner: okta (system)
2021-04-25T22:01:37.370Z        INFO    eslegclient/connection.go:99    elasticsearch url: https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443
2021-04-25T22:01:37.370Z        DEBUG   [esclientleg]   eslegclient/connection.go:290   ES Ping(url=https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443)
2021-04-25T22:01:37.933Z        DEBUG   [esclientleg]   eslegclient/connection.go:313   Ping status code: 200
2021-04-25T22:01:37.933Z        INFO    [esclientleg]   eslegclient/connection.go:314   Attempting to connect to Elasticsearch version 7.12.0
2021-04-25T22:01:37.933Z        DEBUG   [modules]       fileset/pipelines.go:67 Required processors: [{geoip ingest-geoip}]
2021-04-25T22:01:37.933Z        DEBUG   [esclientleg]   eslegclient/connection.go:364   GET https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443/_nodes/ingest  <nil>
2021-04-25T22:01:38.033Z        DEBUG   [esclientleg]   eslegclient/connection.go:364   GET https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443/_ingest/pipeline/filebeat-7.12.0-okta-system-pipeline  <nil>
2021-04-25T22:01:38.137Z        DEBUG   [modules]       fileset/pipelines.go:120        Pipeline already exists in Elasticsearch.       {"pipeline": "filebeat-7.12.0-okta-system-pipeline"}
2021-04-25T22:01:38.137Z        INFO    cfgfile/reload.go:224   Loading of config files completed.
2021-04-25T22:01:38.137Z        INFO    [input.tcp]     tcp/input.go:105        Starting TCP input      {"address": "localhost:9100"}
2021-04-25T22:01:38.138Z        INFO    [tcp]   streaming/listener.go:120       Started listening for TCP connection    {"address": "localhost:9100"}
2021-04-25T22:01:48.138Z        DEBUG   [input] input/input.go:139      Run input
2021-04-25T22:01:58.139Z        DEBUG   [input] input/input.go:139      Run input
2021-04-25T22:01:58.454Z        DEBUG   [tcp]   streaming/listener.go:149       New client      {"address": "localhost:9100", "remote_address": "127.0.0.1:56894", "total": 1}
2021-04-25T22:01:58.466Z        DEBUG   [processors]    processing/processors.go:203    Publish event: {
  "@timestamp": "2021-04-25T22:01:58.465Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.12.0",
    "pipeline": "filebeat-7.12.0-okta-system-pipeline"
  },
  "tags": [
    "forwarded"
  ],
  "fileset": {
    "name": "system"
  },
  "json": {
    // my event is here
    },
  "event": {
    "module": "okta",
    "dataset": "okta.system",
    "original": "{

    //my original event is here
    }"
  },
  "service": {
    "type": "okta"
  },
  "cloud": {
    "availability_zone": "",
    "provider": "openstack",
    "machine": {
      "type": ""
    },
    "instance": {
      "name": "servername",
      "id": "c00dfcfc6faa4b2aaeba802xxxxxxxxx"
    }
  }
}
2021-04-25T22:01:58.466Z        DEBUG   [tcp]   streaming/listener.go:163       client disconnected     {"address": "localhost:9100", "remote_address": "127.0.0.1:56894", "total": 1}
2021-04-25T22:01:59.467Z        INFO    [publisher_pipeline_output]     pipeline/output.go:143  Connecting to backoff(elasticsearch(https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443))
2021-04-25T22:01:59.467Z        DEBUG   [esclientleg]   eslegclient/connection.go:290   ES Ping(url=https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443)
2021-04-25T22:01:59.468Z        INFO    [publisher]     pipeline/retry.go:219   retryer: send unwait signal to consumer
2021-04-25T22:01:59.468Z        INFO    [publisher]     pipeline/retry.go:223     done
2021-04-25T22:01:59.849Z        DEBUG   [esclientleg]   eslegclient/connection.go:313   Ping status code: 200
2021-04-25T22:01:59.849Z        INFO    [esclientleg]   eslegclient/connection.go:314   Attempting to connect to Elasticsearch version 7.12.0
2021-04-25T22:01:59.849Z        DEBUG   [esclientleg]   eslegclient/connection.go:364   GET https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443/_license?human=false  <nil>
2021-04-25T22:01:59.939Z        DEBUG   [license]       licenser/check.go:31    Checking that license covers %sBasic
2021-04-25T22:01:59.939Z        INFO    [license]       licenser/es_callback.go:51      Elasticsearch license: Platinum
2021-04-25T22:01:59.939Z        DEBUG   [modules]       fileset/pipelines.go:67 Required processors: [{geoip ingest-geoip}]
2021-04-25T22:01:59.939Z        DEBUG   [esclientleg]   eslegclient/connection.go:364   GET https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443/_nodes/ingest  <nil>
2021-04-25T22:02:00.028Z        DEBUG   [esclientleg]   eslegclient/connection.go:290   ES Ping(url=https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443)
2021-04-25T22:02:00.116Z        DEBUG   [esclientleg]   eslegclient/connection.go:313   Ping status code: 200
2021-04-25T22:02:00.116Z        INFO    [esclientleg]   eslegclient/connection.go:314   Attempting to connect to Elasticsearch version 7.12.0
2021-04-25T22:02:00.119Z        DEBUG   [esclientleg]   eslegclient/connection.go:364   GET https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443/_ingest/pipeline/filebeat-7.12.0-okta-system-pipeline  <nil>
2021-04-25T22:02:00.209Z        DEBUG   [modules]       fileset/pipelines.go:120        Pipeline already exists in Elasticsearch.       {"pipeline": "filebeat-7.12.0-okta-system-pipeline"}
2021-04-25T22:02:00.209Z        DEBUG   [esclientleg]   eslegclient/connection.go:364   GET https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443/_xpack  <nil>
2021-04-25T22:02:00.297Z        INFO    [index-management]      idxmgmt/std.go:261      Auto ILM enable success.
2021-04-25T22:02:00.297Z        DEBUG   [esclientleg]   eslegclient/connection.go:364   GET https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443/_ilm/policy/filebeat  <nil>
2021-04-25T22:02:00.386Z        INFO    [index-management.ilm]  ilm/std.go:139  do not generate ilm policy: exists=true, overwrite=false
2021-04-25T22:02:00.386Z        INFO    [index-management]      idxmgmt/std.go:274      ILM policy successfully loaded.
2021-04-25T22:02:00.386Z        INFO    [index-management]      idxmgmt/std.go:407      Set setup.template.name to '{filebeat-7.12.0 {now/d}-000001}' as ILM is enabled.
2021-04-25T22:02:00.387Z        INFO    [index-management]      idxmgmt/std.go:412      Set setup.template.pattern to 'filebeat-7.12.0-*' as ILM is enabled.
2021-04-25T22:02:00.387Z        INFO    [index-management]      idxmgmt/std.go:446      Set settings.index.lifecycle.rollover_alias in template to {filebeat-7.12.0 {now/d}-000001} as ILM is enabled.
2021-04-25T22:02:00.387Z        INFO    [index-management]      idxmgmt/std.go:450      Set settings.index.lifecycle.name in template to {filebeat {"policy":{"phases":{"hot":{"actions":{"rollover":{"max_age":"30d","max_size":"50gb"}}}}}}} as ILM is enabled.
2021-04-25T22:02:00.387Z        DEBUG   [esclientleg]   eslegclient/connection.go:364   GET https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443/_cat/templates/filebeat-7.12.0  <nil>
2021-04-25T22:02:00.494Z        INFO    template/load.go:97     Template filebeat-7.12.0 already exists and will not be overwritten.
2021-04-25T22:02:00.494Z        INFO    [index-management]      idxmgmt/std.go:298      Loaded index template.
2021-04-25T22:02:00.494Z        DEBUG   [esclientleg]   eslegclient/connection.go:364   GET https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443/_alias/filebeat-7.12.0  <nil>
2021-04-25T22:02:00.585Z        INFO    [index-management]      idxmgmt/std.go:309      Write alias successfully generated.
2021-04-25T22:02:00.585Z        DEBUG   [esclientleg]   eslegclient/connection.go:364   GET https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443/  <nil>
2021-04-25T22:02:00.672Z        INFO    [publisher_pipeline_output]     pipeline/output.go:151  Connection to backoff(elasticsearch(https://60caa01658d945f7863xxxxxxxxxxxxx.us-east-1.aws.found.io:443)) established
2021-04-25T22:02:00.772Z        DEBUG   [elasticsearch] elasticsearch/client.go:230     PublishEvents: 1 events have been published to elasticsearch in 99.938957ms.
2021-04-25T22:02:00.772Z        DEBUG   [publisher]     memqueue/ackloop.go:160 ackloop: receive ack [0: 0, 1]
2021-04-25T22:02:00.772Z        DEBUG   [publisher]     memqueue/eventloop.go:535       broker ACK events: count=1, start-seq=1, end-seq=1
2021-04-25T22:02:00.772Z        DEBUG   [acker] beater/acker.go:64      stateless ack   {"count": 1}
2021-04-25T22:02:00.773Z        DEBUG   [publisher]     memqueue/ackloop.go:128 ackloop: return ack to broker loop:1
2021-04-25T22:02:00.773Z        DEBUG   [publisher]     memqueue/ackloop.go:131 ackloop:  done send ack

the question is if in the Publish event line (which contains whole JSON event) I should see the event that already passed through the pipeline or it is the event prior to pipeline.

because the publish event does not have necessary changes by pipeline.

2021-04-25T22:01:58.466Z        DEBUG   [processors]    processing/processors.go:203    Publish event: {

stephenb · April 28, 2021, 2:50pm

The filebeat publish events debug shows what the event looks like leaving filebeat (including processors if any on the filebeat side.

The ingest pipeline is on the elasticsearch side not on the filebeat side so you will not see that results with the filebeat publish.

Did you enable the OKTA module and then run the following before you started filebeat?

filebeat setup -e

That loads all the templates, ingest pipelines etc into elasticsearch.

It does look like the pipeline is there

2021-04-25T22:01:38.137Z        DEBUG   [modules]       fileset/pipelines.go:120        Pipeline already exists in Elasticsearch.       {"pipeline": "filebeat-7.12.0-okta-system-pipeline"}

What does the document look like on the elasticsearch side?

Can you share your filebeat.yml and okta.yml configuration?

Did you customized the config?

Leon21 · April 30, 2021, 12:32pm

Thanks for your reply. @stephenb
Yes I started filebeat with setup before running it.

on the ES side on the filebeat index (in the index management) I see index_failed counter increased each time I send an event via filebeat.
I do not see any parsing error for the json object in the filebeat event output and it seems the event is ok.

the filebeat.yml is the default config. I just added ES Cloud ID and user/passes all of the other configs are untouched.

the things that seems to be important is I changed the input section of module to a TCP listener

type: tcp
host: "localhost:9100"
max_message_size: 10MiB
#framing: rfc6587

tags: {{.tags | tojson}}
publisher_pipeline.disable_host: {{ inList .tags "forwarded" }}

processors:
  - decode_json_fields:
      fields:
        - message
      target: json
{{ if eq .keep_original_message true }}
  - rename:
      fields:
        - from: message
          to: event.original
{{ end }}
  - add_fields:
      target: ''
      fields:
        ecs.version: 1.8.0

so I get the json from TCP listener then push it to ES.

and from the point you mentioned I found that event is published from filebeat correctly but when it reaches ES it faces "index failed" without any ingest parsing errors in ingest pipeline.

note: I tested the pipeline with the sample ''publish event" in the ES console (add document) and it worked without any issue and converted the event successfully without any parsing errors. but when the same event goes through filebeat I see index failed count increased. instead of count of documents I mean.

stephenb · April 30, 2021, 1:45pm

Hi @Leon21

Apologies, I think in order to help I need 3 things

Your full filebeat.yml (sans creds) the okta.yml and filebeat logs after it run for a few so I can see more after it published the event. There should be a log line with that days non zero metrics....

I think perhaps when you re-defined the input it means that you are no longer actually using the module.. i.e the ingest pipeline is not getting called and thus the message is failing to ingest.

The solution will probably be

use the module as it is intended
it in the tcp input manually define the pipeline as shown here This may or may not work as the module may be doing some processing on the filebeat side but hopefully it will work as you said it work when you tested in the ES console (did it actually index or did you do _simulate).

system · May 28, 2021, 3:46pm

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Okta filebeat module ingest pipeline not running Beats filebeat	4	338	September 16, 2021
Elastic Cloud Output not working Tshoot Beats filebeat	6	413	May 24, 2021
Filebeat output to file Beats filebeat	18	2121	October 10, 2022
Filebeat dashboards are not loaded in kibana---filebeat version 7.10 Beats filebeat	5	637	January 5, 2021
Issues with Filebeat, how to debug? Beats filebeat	5	562	June 19, 2022

Filebeat Pipeline debug output Publish event

Related topics