FileBeat fails to process large log files of some MBs

Elastic Stack Beats
1

Hi,

I am new to ELK stack. Done the setup of elastic, Kibana , Logstash and filebeat to process the files.
If i configure path of log file which in some KBs(2-3KB) then i am able to process file successfully. I would like to read only Error and Warning logs not debug logs.
When i tried to process large file of size 2.5MB then i could see filebeat takes lots of time(around 1 hr) to process it and finally i could not see any logs processed to logstash.

Below is my configurations

Filebeat configurations:

#============= Filebeat inputs =============================

filebeat.inputs:



- type: log

  # Change to true to enable this input configuration.
  enabled: true

  # Paths that should be crawled and fetched. Glob based paths.
  paths:
    - /home/anand/cucumbertests/callingcard/06_07_20_114537/VoucherException/*.log
 
  #include_lines: ['^ERR', '^WARN']
  include_lines: ['^(?:[0-9]{4}-[0-9]{2}-[0-9]{2})?(?:[ T][0-9]{2}:[0-9]{2}:[0-9]{2})?(?:[.,][0-9]{3})?(\s(ERROR|WARN))']

  # Optional additional fields. These fields can be freely picked
  # to add additional information to the crawled log files for filtering
  fields:
    type: mylog
  #  review: 1
  
  fields_under_root: true
  
  ### Multiline options

  multiline.pattern: '^[[:space:]]+(at|\.{3})[[:space:]]+\b|^Caused by:'
  multiline.negate: false
  multiline.match: after


#============ Filebeat modules ===============================

filebeat.config.modules:
  # Glob pattern for configuration loading
  path: ${path.config}/modules.d/*.yml

  # Set to true to enable config reloading
  reload.enabled: false

#======== Elasticsearch template setting ==========================

setup.template.settings:
  index.number_of_shards: 1
  #index.codec: best_compression
  #_source.enabled: false

#----------------------------- Logstash output --------------------------------
output.logstash:
  # The Logstash hosts
  hosts: ["15.112.156.206:5044"]

 
#=== Processors ==============

# Configure processors to enhance or manipulate events generated by the beat.

processors:
  - add_host_metadata: ~
  - add_cloud_metadata: ~

Logstash Configurations:

 
input {
  beats {
    port => 5044
  }
  beats {
    port => 5045
  }
}

filter {
  if [type] == "mylog" {
    grok {
      match => { "message" => "(?m)%{TIMESTAMP_ISO8601:cclogdate} %{LOGLEVEL:ccseverity} \[%{JAVACLASS:ccpackage}\] \(%{GREEDYDATA:ccthread}\) \<%{GREEDYDATA:ccappsession}\> (?<cclogmessage>[^{}]*)" }
      add_field => [ "received_at", "%{@timestamp}" ]
      add_field => [ "received_from", "%{ccpackage}" ]
    }
    date {
      match => [ "logdate", "YYYY-MM-dd HH:mm:ss,SSS" ]
    }
  }
  else if [type] == "mylog1" {
    grok {
      match => { "message" => "(?m)%{TIMESTAMP_ISO8601:cclogdate} %{LOGLEVEL:ccseverity} \[%{JAVACLASS:ccpackage}\] \(%{GREEDYDATA:ccthread}\) \<%{GREEDYDATA:ccappsession}\> (?<cclogmessage>[^{}]*)" }
      add_field => [ "received_at", "%{@timestamp}" ]
    }
    date {
      match => [ "logdate", "YYYY-MM-dd HH:mm:ss,SSS" ]
    }
  }
  else {
    xml 
    {
        namespaces => {
          "xmlns" => "http://www.hp.com/ocmp/2004/03/cdr"
          "xmlns:debug" => "http://www.hp.com/ocmp/2004/03/cdr-debug"
          "xmlns:log" => "http://www.hp.com/ocmp/2004/03/cdr-log"
        }
        source => "message"
        remove_namespaces => "true"
        xpath => 
        [
            "//CDR/@sessionid", "SessionID",
            "//CDR/@starttime", "CallStartTime",
            "//CDR/@stoptime", "CallStopTime",
            "//CDR/@serviceid", "ServiceID",
            "//CDR/CC_CollectVoucher_OK/text()", "VoucherID",
            "//CDR/Application.Info/text()", "ApplicationInfo",
            "//CDR/Application.Info[last()]/text()", "CallResultCode",            
            "//CDR/CC_AnumberIsPrisioner/text()", "IsPrisinor",            
            "//CDR/CC_CCRT_Diameter_OK/text()", "DiameterResponse"
              
        ]
        store_xml => false
    }
    
  }
}

output {
  elasticsearch {
    hosts => ["http://localhost:9200"]
    index => "ccreportabclog-%{+YYYY.MM.dd}"
    #user => "elastic"
    #password => "changeme"
  }
  stdout { codec =>rubydebug}
}

Can some suggest what needs to be done to fix this issue.

2

At first, you need to identify the bottleneck: Filebeat/Logstash
Instead of sending data directly to Logstash, please use stdout for output of Filebeat.
Below Is the configuration :

output {
	stdout { 
	     codec => rubydebug { } 
	}
}

Also, you can use exclude_lines processor for excluding debugging logs

Please try out the above suggestions and post the results

3

Hi Abhishek,

Thanks a lot for your reply.

With below configuration which I have used in filebeat config file, I am able to exclude Debug logs.

include_lines: ['^(?:[0-9]{4}-[0-9]{2}-[0-9]{2})?(?:[ T][0-9]{2}:[0-9]{2}:[0-9]{2})?(?:[.,][0-9]{3})?(\s(ERROR|WARN))']

Regarding file processing, I have one more observation for processing 2MB file. I tried with 2 different files of same size, filebeat is able to process both files but time taken for processing them is different.
Lets say fileA.log and fileB.log. to process fileA.log it takes 4 sec and to process fileB.log it takes half an hour. For your info both files has similar pattern but different content. Is there any issue with file content?

One more test I have done ie I have copied some data from fileB.log to fileC.log(size of 1MB half of original size), then filebeat took around 15 mins(half of original time) to process the file. Time is increasing/decreasing with size of file.

Let me try to output filebeat logs and share the results

Thanks and Regards,
Shwetha

4

Can you also run one more experiment by disabling the multiline processor ?

Thanks

5

Hi Abhishek,

For further simlification I have taken only 55kb of data from both files(FileA.log and FileB.log). Disabled multiline configuration and enabled console output in filebeat.

#=========================== Filebeat inputs =============================

filebeat.inputs:

- type: log

  # Change to true to enable this input configuration.
  enabled: true

  # Paths that should be crawled and fetched. Glob based paths.
  paths:
    - /home/anand/cucumbertests/delete/testWorking.log
  
  #include_lines: ['^ERR', '^WARN']
  include_lines: ['^(?:[0-9]{4}-[0-9]{2}-[0-9]{2})?(?:[ T][0-9]{2}:[0-9]{2}:[0-9]{2})?(?:[.,][0-9]{3})?(\s(ERROR|WARN))']

  # Optional additional fields. These fields can be freely picked
  fields:
    type: mylog
  #  review: 1

  fields_under_root: true
 #============================= Filebeat modules ===============================

filebeat.config.modules:
  # Glob pattern for configuration loading
  path: ${path.config}/modules.d/*.yml

  # Set to true to enable config reloading
  reload.enabled: false

  # Period on which files under path should be checked for changes
  #reload.period: 10s

#==================== Elasticsearch template setting ==========================

setup.template.settings:
  index.number_of_shards: 1
  #index.codec: best_compression
  #_source.enabled: false
  
#================================ Outputs =====================================

# Configure what output to use when sending the data collected by the beat.

output.console:
  codec.json:
    pretty: true
    escape_html: false
6

Below is filebeat console ouput.
For FileB.log filebeat took almost one minute. Filebeat started harvesting file at 10:09:10.418Z and error logs populated to console at 10:10:13.460Z

filebeat console output for FileB.log

[root@tef3 filebeat-7.0.1-linux-x86_64]# 2020-07-13T10:09:09.365Z       INFO    instance/beat.go:571    Home path: [/var/ccelk/filebeat-7.0.1-linux-x86_64] Config path: [/var/ccelk/filebeat-7.0.1-linux-x86_64] Data path: [/var/ccelk/filebeat-7.0.1-linux-x86_64/data] Logs path: [/var/ccelk/filebeat-7.0.1-linux-x86_64/logs]
2020-07-13T10:09:09.828Z        INFO    instance/beat.go:579    Beat ID: 937868cc-5c1e-430c-a606-ca27eb6310f5
2020-07-13T10:09:09.828Z        INFO    [index-management.ilm]  ilm/ilm.go:129  Policy name: filebeat-7.0.1
2020-07-13T10:09:09.831Z        INFO    [seccomp]       seccomp/seccomp.go:93   Syscall filter could not be installed because the kernel does not support seccomp
2020-07-13T10:09:09.832Z        INFO    [beat]  instance/beat.go:827    Beat info       {"system_info": {"beat": {"path": {"config": "/var/ccelk/filebeat-7.0.1-linux-x86_64", "data": "/var/ccelk/filebeat-7.0.1-linux-x86_64/data", "home": "/var/ccelk/filebeat-7.0.1-linux-x86_64", "logs": "/var/ccelk/filebeat-7.0.1-linux-x86_64/logs"}, "type": "filebeat", "uuid": "937868cc-5c1e-430c-a606-ca27eb6310f5"}}}
2020-07-13T10:09:09.832Z        INFO    [beat]  instance/beat.go:836    Build info      {"system_info": {"build": {"commit": "cbffb4dcc8d1d2b0ef2078cb7d7546092ee86e57", "libbeat": "7.0.1", "time": "2019-04-29T12:09:21.000Z", "version": "7.0.1"}}}
2020-07-13T10:09:09.832Z        INFO    [beat]  instance/beat.go:839    Go runtime info {"system_info": {"go": {"os":"linux","arch":"amd64","max_procs":8,"version":"go1.11.5"}}}
2020-07-13T10:09:09.833Z        INFO    [beat]  instance/beat.go:843    Host info       {"system_info": {"host": {"architecture":"x86_64","boot_time":"2019-12-04T12:22:27Z","containerized":true,"name":"tef3.localdomain","ip":["127.0.0.1/8","::1/128","15.112.155.23/21","fe80::250:56ff:fe86:d33a/64","192.168.122.1/24"],"kernel_version":"2.6.32-696.el6.x86_64","mac":["00:50:56:86:d3:3a","52:54:00:e0:bb:5a","52:54:00:e0:bb:5a"],"os":{"family":"redhat","platform":"redhat","name":"Red","version":"6.9 (Santiago)","major":6,"minor":9,"patch":0,"codename":"Santiago"},"timezone":"UTC","timezone_offset_sec":0,"id":"3a3653c3f20c73adeb4a3d630000031c"}}}
2020-07-13T10:09:09.834Z        INFO    [beat]  instance/beat.go:872    Process info    {"system_info": {"process": {"capabilities": {"inheritable":null,"permitted":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend","audit_read","38","39","40","41","42","43","44","45","46","47","48","49","50","51","52","53","54","55","56","57","58","59","60","61","62","63"],"effective":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend","audit_read","38","39","40","41","42","43","44","45","46","47","48","49","50","51","52","53","54","55","56","57","58","59","60","61","62","63"],"bounding":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend","audit_read","38","39","40","41","42","43","44","45","46","47","48","49","50","51","52","53","54","55","56","57","58","59","60","61","62","63"],"ambient":null}, "cwd": "/var/ccelk/filebeat-7.0.1-linux-x86_64", "exe": "/var/ccelk/filebeat-7.0.1-linux-x86_64/filebeat", "name": "filebeat", "pid": 11756, "ppid": 11287, "seccomp": {"mode":""}, "start_time": "2020-07-13T10:09:08.500Z"}}}
2020-07-13T10:09:09.834Z        INFO    instance/beat.go:280    Setup Beat: filebeat; Version: 7.0.1
2020-07-13T10:09:09.891Z        INFO    [publisher]     pipeline/module.go:97   Beat name: tef3.localdomain
2020-07-13T10:09:09.892Z        INFO    [monitoring]    log/log.go:117  Starting metrics logging every 30s
2020-07-13T10:09:09.892Z        INFO    instance/beat.go:391    filebeat start running.
2020-07-13T10:09:09.892Z        INFO    registrar/migrate.go:104        No registry home found. Create: /var/ccelk/filebeat-7.0.1-linux-x86_64/data/registry/filebeat
2020-07-13T10:09:09.893Z        INFO    registrar/migrate.go:112        Initialize registry meta file
2020-07-13T10:09:10.103Z        INFO    registrar/registrar.go:108      No registry file found under: /var/ccelk/filebeat-7.0.1-linux-x86_64/data/registry/filebeat/data.json. Creating a new registry file.
2020-07-13T10:09:10.416Z        INFO    registrar/registrar.go:145      Loading registrar data from /var/ccelk/filebeat-7.0.1-linux-x86_64/data/registry/filebeat/data.json
2020-07-13T10:09:10.416Z        INFO    registrar/registrar.go:152      States Loaded from registrar: 0
2020-07-13T10:09:10.416Z        WARN    beater/filebeat.go:357  Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2020-07-13T10:09:10.416Z        INFO    crawler/crawler.go:72   Loading Inputs: 1
2020-07-13T10:09:10.417Z        INFO    log/input.go:138        Configured paths: [/home/anand/cucumbertests/delete/testno.log]
2020-07-13T10:09:10.417Z        INFO    input/input.go:114      Starting input of type: log; ID: 16296832146253287836
2020-07-13T10:09:10.418Z        INFO    crawler/crawler.go:106  Loading and starting Inputs completed. Enabled inputs: 1
2020-07-13T10:09:10.418Z        INFO    cfgfile/reload.go:150   Config reloader started
2020-07-13T10:09:10.418Z        INFO    cfgfile/reload.go:205   Loading of config files completed.
2020-07-13T10:09:10.418Z        INFO    log/harvester.go:254    Harvester started for file: /home/anand/cucumbertests/delete/testno.log
2020-07-13T10:09:12.832Z        INFO    add_cloud_metadata/add_cloud_metadata.go:346    add_cloud_metadata: hosting provider type not detected.
2020-07-13T10:09:39.896Z        INFO    [monitoring]    log/log.go:144  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":280,"time":{"ms":284}},"total":{"ticks":460,"time":{"ms":471},"value":460},"user":{"ticks":180,"time":{"ms":187}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":8},"info":{"ephemeral_id":"b225d3c0-41e7-4e5e-9ef6-8f4cfcb79440","uptime":{"ms":30553}},"memstats":{"gc_next":4194304,"memory_alloc":2051712,"memory_total":6809296,"rss":27127808}},"filebeat":{"events":{"active":5,"added":91,"done":86},"harvester":{"open_files":1,"running":1,"started":1}},"libbeat":{"config":{"module":{"running":0},"reloads":1},"output":{"type":"console"},"pipeline":{"clients":1,"events":{"active":1,"filtered":90,"total":91}}},"registrar":{"states":{"current":1,"update":87},"writes":{"success":87,"total":88}},"system":{"cpu":{"cores":8},"load":{"1":1.61,"15":0.88,"5":1.02,"norm":{"1":0.2013,"15":0.11,"5":0.1275}}}}}}
2020-07-13T10:10:09.895Z        INFO    [monitoring]    log/log.go:144  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":480,"time":{"ms":198}},"total":{"ticks":750,"time":{"ms":288},"value":750},"user":{"ticks":270,"time":{"ms":90}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":8},"info":{"ephemeral_id":"b225d3c0-41e7-4e5e-9ef6-8f4cfcb79440","uptime":{"ms":60551}},"memstats":{"gc_next":4194304,"memory_alloc":2722272,"memory_total":7479856,"rss":45056}},"filebeat":{"events":{"added":92,"done":92},"harvester":{"open_files":1,"running":1}},"libbeat":{"config":{"module":{"running":0}},"pipeline":{"clients":1,"events":{"active":1,"filtered":92,"total":92}}},"registrar":{"states":{"current":1,"update":92},"writes":{"success":92,"total":92}},"system":{"load":{"1":2.02,"15":0.93,"5":1.18,"norm":{"1":0.2525,"15":0.1163,"5":0.1475}}}}}}
{
  "@timestamp": "2020-07-13T10:10:13.460Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.0.1"
  },
  "agent": {
    "version": "7.0.1",
    "type": "filebeat",
    "ephemeral_id": "b225d3c0-41e7-4e5e-9ef6-8f4cfcb79440",
    "hostname": "tef3.localdomain",
    "id": "937868cc-5c1e-430c-a606-ca27eb6310f5"
  },
  "log": {
    "offset": 49266,
    "file": {
      "path": "/home/anand/cucumbertests/delete/testno.log"
    }
  },
  "message": "2020-07-02 10:09:27,670 ERROR [fr.marben.diameter] (THREAD-TRANSPORT-IN) <> Exception java.io.IOException: Connection reset by peer(Connection reset by peer) caught, thrown by socketChannel.read in checkClosed method",
  "type": "mylog",
  "input": {
    "type": "log"
  },
  "ecs": {
    "version": "1.0.0"
  },
  "host": {
    "name": "tef3.localdomain",
    "containerized": true,
    "hostname": "tef3.localdomain",
    "architecture": "x86_64",
    "os": {
      "codename": "Santiago",
      "platform": "redhat",
      "version": "6.9 (Santiago)",
      "family": "redhat",
      "name": "Red",
      "kernel": "2.6.32-696.el6.x86_64"
    },
    "id": "3a3653c3f20c73adeb4a3d630000031c"
  }
}
{
  "@timestamp": "2020-07-13T10:10:13.460Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.0.1"
  },
  "log": {
    "offset": 49484,
    "file": {
      "path": "/home/anand/cucumbertests/delete/testno.log"
    }
  },
  "message": "2020-07-02 10:09:27,674 ERROR [com.hp.opencall.coam.ntf.producerImpl.AlarmNotificationImpl] (THREAD-PEER(DELO2SIM3)) <> AlarmNotification attributes are: ",
  "input": {
    "type": "log"
  },
  "type": "mylog",
  "host": {
    "os": {
      "family": "redhat",
      "name": "Red",
      "kernel": "2.6.32-696.el6.x86_64",
      "codename": "Santiago",
      "platform": "redhat",
      "version": "6.9 (Santiago)"
    },
    "id": "3a3653c3f20c73adeb4a3d630000031c",
    "containerized": true,
    "hostname": "tef3.localdomain",
    "name": "tef3.localdomain",
    "architecture": "x86_64"
  },
  "agent": {
    "version": "7.0.1",
    "type": "filebeat",
    "ephemeral_id": "b225d3c0-41e7-4e5e-9ef6-8f4cfcb79440",
    "hostname": "tef3.localdomain",
    "id": "937868cc-5c1e-430c-a606-ca27eb6310f5"
  },
  "ecs": {
    "version": "1.0.0"
  }
}
{
  "@timestamp": "2020-07-13T10:10:13.460Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.0.1"
  },
  "log": {
    "offset": 50679,
    "file": {
      "path": "/home/anand/cucumbertests/delete/testno.log"
    }
  },
  "message": "2020-07-02 10:09:27,675 ERROR [com.hp.opencall.coam.ntf.producerImpl.AlarmNotificationImpl] (pool-5-thread-4) <> AlarmNotification attributes are: ",
  "input": {
    "type": "log"
  },
  "type": "mylog",
  "ecs": {
    "version": "1.0.0"
  },
  "host": {
    "os": {
      "kernel": "2.6.32-696.el6.x86_64",
      "codename": "Santiago",
      "platform": "redhat",
      "version": "6.9 (Santiago)",
      "family": "redhat",
      "name": "Red"
    },
    "id": "3a3653c3f20c73adeb4a3d630000031c",
    "name": "tef3.localdomain",
    "containerized": true,
    "hostname": "tef3.localdomain",
    "architecture": "x86_64"
  },
  "agent": {
    "id": "937868cc-5c1e-430c-a606-ca27eb6310f5",
    "version": "7.0.1",
    "type": "filebeat",
    "ephemeral_id": "b225d3c0-41e7-4e5e-9ef6-8f4cfcb79440",
    "hostname": "tef3.localdomain"
  }
}
7

For FileA.log as soon as filebeat harvester started reading file I could see error logs in console output. Filebeat started harvesting file at 10:19:38.363Z and error logs populated to console at 10:19:38.363Z

filebeat console output for FileA.log

[root@tef3 filebeat-7.0.1-linux-x86_64]# 2020-07-13T10:19:37.603Z       INFO    instance/beat.go:571    Home path: [/var/ccelk/filebeat-7.0.1-linux-x86_64] Config path: [/var/ccelk/filebeat-7.0.1-linux-x86_64] Data path: [/var/ccelk/filebeat-7.0.1-linux-x86_64/data] Logs path: [/var/ccelk/filebeat-7.0.1-linux-x86_64/logs]
2020-07-13T10:19:38.009Z        INFO    instance/beat.go:579    Beat ID: d74bdb87-8656-4f87-b9a0-6989300c86d2
2020-07-13T10:19:38.009Z        INFO    [index-management.ilm]  ilm/ilm.go:129  Policy name: filebeat-7.0.1
2020-07-13T10:19:38.012Z        INFO    [seccomp]       seccomp/seccomp.go:93   Syscall filter could not be installed because the kernel does not support seccomp
2020-07-13T10:19:38.012Z        INFO    [beat]  instance/beat.go:827    Beat info       {"system_info": {"beat": {"path": {"config": "/var/ccelk/filebeat-7.0.1-linux-x86_64", "data": "/var/ccelk/filebeat-7.0.1-linux-x86_64/data", "home": "/var/ccelk/filebeat-7.0.1-linux-x86_64", "logs": "/var/ccelk/filebeat-7.0.1-linux-x86_64/logs"}, "type": "filebeat", "uuid": "d74bdb87-8656-4f87-b9a0-6989300c86d2"}}}
2020-07-13T10:19:38.012Z        INFO    [beat]  instance/beat.go:836    Build info      {"system_info": {"build": {"commit": "cbffb4dcc8d1d2b0ef2078cb7d7546092ee86e57", "libbeat": "7.0.1", "time": "2019-04-29T12:09:21.000Z", "version": "7.0.1"}}}
2020-07-13T10:19:38.012Z        INFO    [beat]  instance/beat.go:839    Go runtime info {"system_info": {"go": {"os":"linux","arch":"amd64","max_procs":8,"version":"go1.11.5"}}}
2020-07-13T10:19:38.014Z        INFO    [beat]  instance/beat.go:843    Host info       {"system_info": {"host": {"architecture":"x86_64","boot_time":"2019-12-04T12:22:27Z","containerized":true,"name":"tef3.localdomain","ip":["127.0.0.1/8","::1/128","15.112.155.23/21","fe80::250:56ff:fe86:d33a/64","192.168.122.1/24"],"kernel_version":"2.6.32-696.el6.x86_64","mac":["00:50:56:86:d3:3a","52:54:00:e0:bb:5a","52:54:00:e0:bb:5a"],"os":{"family":"redhat","platform":"redhat","name":"Red","version":"6.9 (Santiago)","major":6,"minor":9,"patch":0,"codename":"Santiago"},"timezone":"UTC","timezone_offset_sec":0,"id":"3a3653c3f20c73adeb4a3d630000031c"}}}
2020-07-13T10:19:38.014Z        INFO    [beat]  instance/beat.go:872    Process info    {"system_info": {"process": {"capabilities": {"inheritable":null,"permitted":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend","audit_read","38","39","40","41","42","43","44","45","46","47","48","49","50","51","52","53","54","55","56","57","58","59","60","61","62","63"],"effective":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend","audit_read","38","39","40","41","42","43","44","45","46","47","48","49","50","51","52","53","54","55","56","57","58","59","60","61","62","63"],"bounding":["chown","dac_override","dac_read_search","fowner","fsetid","kill","setgid","setuid","setpcap","linux_immutable","net_bind_service","net_broadcast","net_admin","net_raw","ipc_lock","ipc_owner","sys_module","sys_rawio","sys_chroot","sys_ptrace","sys_pacct","sys_admin","sys_boot","sys_nice","sys_resource","sys_time","sys_tty_config","mknod","lease","audit_write","audit_control","setfcap","mac_override","mac_admin","syslog","wake_alarm","block_suspend","audit_read","38","39","40","41","42","43","44","45","46","47","48","49","50","51","52","53","54","55","56","57","58","59","60","61","62","63"],"ambient":null}, "cwd": "/var/ccelk/filebeat-7.0.1-linux-x86_64", "exe": "/var/ccelk/filebeat-7.0.1-linux-x86_64/filebeat", "name": "filebeat", "pid": 12604, "ppid": 11287, "seccomp": {"mode":""}, "start_time": "2020-07-13T10:19:36.700Z"}}}
2020-07-13T10:19:38.015Z        INFO    instance/beat.go:280    Setup Beat: filebeat; Version: 7.0.1
2020-07-13T10:19:38.015Z        INFO    [publisher]     pipeline/module.go:97   Beat name: tef3.localdomain
2020-07-13T10:19:38.016Z        INFO    [monitoring]    log/log.go:117  Starting metrics logging every 30s
2020-07-13T10:19:38.016Z        INFO    instance/beat.go:391    filebeat start running.
2020-07-13T10:19:38.016Z        INFO    registrar/migrate.go:104        No registry home found. Create: /var/ccelk/filebeat-7.0.1-linux-x86_64/data/registry/filebeat
2020-07-13T10:19:38.016Z        INFO    registrar/migrate.go:112        Initialize registry meta file
2020-07-13T10:19:38.135Z        INFO    registrar/registrar.go:108      No registry file found under: /var/ccelk/filebeat-7.0.1-linux-x86_64/data/registry/filebeat/data.json. Creating a new registry file.
2020-07-13T10:19:38.361Z        INFO    registrar/registrar.go:145      Loading registrar data from /var/ccelk/filebeat-7.0.1-linux-x86_64/data/registry/filebeat/data.json
2020-07-13T10:19:38.361Z        INFO    registrar/registrar.go:152      States Loaded from registrar: 0
2020-07-13T10:19:38.361Z        WARN    beater/filebeat.go:357  Filebeat is unable to load the Ingest Node pipelines for the configured modules because the Elasticsearch output is not configured/enabled. If you have already loaded the Ingest Node pipelines or are using Logstash pipelines, you can ignore this warning.
2020-07-13T10:19:38.361Z        INFO    crawler/crawler.go:72   Loading Inputs: 1
2020-07-13T10:19:38.362Z        INFO    log/input.go:138        Configured paths: [/home/anand/cucumbertests/delete/testWorking.log]
2020-07-13T10:19:38.362Z        INFO    input/input.go:114      Starting input of type: log; ID: 15628362494942694474
2020-07-13T10:19:38.362Z        INFO    crawler/crawler.go:106  Loading and starting Inputs completed. Enabled inputs: 1
2020-07-13T10:19:38.362Z        INFO    cfgfile/reload.go:150   Config reloader started
2020-07-13T10:19:38.363Z        INFO    cfgfile/reload.go:205   Loading of config files completed.
2020-07-13T10:19:38.363Z        INFO    log/harvester.go:254    Harvester started for file: /home/anand/cucumbertests/delete/testWorking.log
2020-07-13T10:19:41.012Z        INFO    add_cloud_metadata/add_cloud_metadata.go:346    add_cloud_metadata: hosting provider type not detected.
{
  "@timestamp": "2020-07-13T10:19:38.363Z",
  "@metadata": {
    "beat": "filebeat",
    "type": "_doc",
    "version": "7.0.1"
  },
  "agent": {
    "ephemeral_id": "0930144c-2f9f-4c9f-b1d7-9d37f8846ab2",
    "hostname": "tef3.localdomain",
    "id": "d74bdb87-8656-4f87-b9a0-6989300c86d2",
    "version": "7.0.1",
    "type": "filebeat"
  },
  "ecs": {
    "version": "1.0.0"
  },
  "log": {
    "offset": 348,
    "file": {
      "path": "/home/anand/cucumbertests/delete/testWorking.log"
    }
  },
  "message": "2020-07-02 10:08:12,965 ERROR [com.hp.opencall.ngin.cdrlog.impl.CommonCdrGenerator] (IMSC SIP-Connector connector's thread for service callingcard-sip_tef3.localdomain_1 - 9) <AppSess=ApplicationSession-1-22729@15.213.56.19> init() initialization was already done.. nothing to do",
  "input": {
    "type": "log"
  },
  "type": "mylog",
  "host": {
    "os": {
      "version": "6.9 (Santiago)",
      "family": "redhat",
      "name": "Red",
      "kernel": "2.6.32-696.el6.x86_64",
      "codename": "Santiago",
      "platform": "redhat"
    },
    "id": "3a3653c3f20c73adeb4a3d630000031c",
    "name": "tef3.localdomain",
    "containerized": true,
    "hostname": "tef3.localdomain",
    "architecture": "x86_64"
  }
}
2020-07-13T10:20:08.019Z        INFO    [monitoring]    log/log.go:144  Non-zero metrics in the last 30s        {"monitoring": {"metrics": {"beat":{"cpu":{"system":{"ticks":30,"time":{"ms":34}},"total":{"ticks":110,"time":{"ms":118},"value":110},"user":{"ticks":80,"time":{"ms":84}}},"handles":{"limit":{"hard":4096,"soft":1024},"open":7},"info":{"ephemeral_id":"0930144c-2f9f-4c9f-b1d7-9d37f8846ab2","uptime":{"ms":30473}},"memstats":{"gc_next":4194304,"memory_alloc":2681160,"memory_total":7299672,"rss":21250048}},"filebeat":{"events":{"added":245,"done":245},"harvester":{"open_files":1,"running":1,"started":1}},"libbeat":{"config":{"module":{"running":0},"reloads":1},"output":{"events":{"acked":1,"batches":1,"total":1},"type":"console","write":{"bytes":1243}},"pipeline":{"clients":1,"events":{"active":0,"filtered":244,"published":1,"total":245},"queue":{"acked":1}}},"registrar":{"states":{"current":1,"update":245},"writes":{"success":4,"total":4}},"system":{"cpu":{"cores":8},"load":{"1":0.79,"15":0.89,"5":0.9,"norm":{"1":0.0988,"15":0.1113,"5":0.1125}}}}}}

Thanks,
Shwetha

8

Hi Abhishek,

I was not able to post all the details in one message so posted under 3 messages , sorry for that

Thanks,
Shwetha N

9

Hi Shweta,
Sorry for late reply but I can't see the error messages in the logs that you posted.
I only found INFO and WARN level logs for FIlebeat.
Please let me know if I am missing something

10

Hi Abhishek,

Sorry for late reply.
Error logs are not actually Error logs on filebeat console, these are our application logs which are populated under server log file as error messages.
As I have mentioned, My application server logs contains lots of logs with different log levels like Debug,Info,Error and Warning. I want File beat to process only Error logs to logstash.
In Filebeat console log (above uploaded ) I can see that logs(Error/warn) from my application log files are getting processed to logstash but looks like file beat is taking lots of time to read and process. In Ideal case my observation was file beat process log file within some seconds(does not matter the log file size) but in my case I can see time is increasing with file size. So just wanted to know what may be the issue?

Thanks
Shwetha

11

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