# Dropping log lines on log rotation

**URL:** <https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036>\
**Category:** Beats\
**Tags:** filebeat\
**Created:** [March 21, 2018, 4:48pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036 "2018-03-21T16:48:23Z")\
**Posts on this page:** 16\
**Page:** 1

<div class="post-metadata">

**Author:** ![DDEFISHER](https://avatars.discourse-cdn.com/v4/letter/d/b9e5f3/32.png) [@DDEFISHER](https://discuss.elastic.co/u/DDEFISHER)\
**Post date:** [March 21, 2018, 4:48pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/1 "2018-03-21T16:48:23Z")

</div>

File beat version: 5.6.3  
os: centos

Occasionally log data will be missing that appears to come after a log rotate. If we have two files "old\_log" and "new\_log" all log lines from "old\_log" will be present but the first couple(could be alot) of "new\_log" will be missing. Also the first line that is picked up from "new\_log" when this happens will not be complete and contain a "\_jsonparsefailure". After the jsonparsefailure everything seems to return to normal but that line and the preceding lines never end up in elasticsearch(presumably never even get shipped to logstash).

quick\_edit: these logs are coming from java applications using logback to log with a time based rolling policy.

relevant configs

```auto
filebeat:
  config_dir: /etc/filebeat/conf.d
  idle_timeout: 5s
  publish_async: false
  registry_file: /var/lib/filebeat/registry
  spool_size: 600
logging:
  files:
    keepfiles: 5
    name: filebeat.log
    path: /var/log/filebeat
    rotateeverybytes: 10485760
  level: info
  to_files: true
  to_syslog: false
output:
  logstash:
    bulk_max_size: 100
    compression_level: 3
    hosts: ['fake-008','fake-009','fake-010','fake-011','fake-012','fake-007']
    loadbalance: true
    max_retries: -1
    worker: 1

```

```auto
filebeat:
  prospectors:
  -
    document_type: service-json
    paths:
      - /usr/local/services/*/log/*-logstash.log
      - /var/log/services/*-logstash.log

```

---

<div class="post-metadata">

**Author:** ![andrewkroh](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/andrewkroh/32/3784_2.png) [@andrewkroh](https://discuss.elastic.co/u/andrewkroh)\
**Post date:** [March 22, 2018, 11:32am UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/2 "2018-03-22T11:32:06Z")

</div>

It would be good to isolate the problem to Filebeat. Can you reproduce the issue if you are only using the [file output](https://www.elastic.co/guide/en/beats/filebeat/5.6/file-output.html)?

Can you please share your Logstash config too.

---

<div class="post-metadata">

**Author:** ![DDEFISHER](https://avatars.discourse-cdn.com/v4/letter/d/b9e5f3/32.png) [@DDEFISHER](https://discuss.elastic.co/u/DDEFISHER)\
**Post date:** [March 22, 2018, 12:27pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/3 "2018-03-22T12:27:53Z")

</div>

I will try to capture this with the file output but I think it will be hard because it does not happen frequently .

version : 5.6.3

logstash.yml

```auto
path.data: /var/lib/logstash
path.config: /etc/logstash/conf.d
path.logs: /var/log/logstash
pipeline.workers: 16
xpack.monitoring.enabled: true
xpack.monitoring.elasticsearch.url: ["http://es-001:9200", "http://es-002:9200", "http://es-003:9200"]

```

---

<div class="post-metadata">

**Author:** ![DDEFISHER](https://avatars.discourse-cdn.com/v4/letter/d/b9e5f3/32.png) [@DDEFISHER](https://discuss.elastic.co/u/DDEFISHER)\
**Post date:** [March 22, 2018, 12:34pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/4 "2018-03-22T12:34:41Z")

</div>

Just wanted to add that I tested our log rotation method to make sure that it was not truncating logs and it appears to be doing what it should be doing by renaming the old file keeping the same inode and creating a new file with a new inode for the new log.

```auto
$ ls -i test*
28583565 test.log
$ ls -i test*
28583578 test.log 28583565 test.log.201803220833

```

---

<div class="post-metadata">

**Author:** ![andrewkroh](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/andrewkroh/32/3784_2.png) [@andrewkroh](https://discuss.elastic.co/u/andrewkroh)\
**Post date:** [March 22, 2018, 12:40pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/5 "2018-03-22T12:40:28Z")

</div>

Please include the configs from `/etc/logstash/conf.d` so we can understand what Logstash is doing with the data.

---

<div class="post-metadata">

**Author:** ![DDEFISHER](https://avatars.discourse-cdn.com/v4/letter/d/b9e5f3/32.png) [@DDEFISHER](https://discuss.elastic.co/u/DDEFISHER)\
**Post date:** [March 22, 2018, 12:52pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/6 "2018-03-22T12:52:46Z")

</div>

I think these are the relevant ones

10-input-filebeat

```auto
input {
  beats {
    port => 10200
    tags => []
  }
}

```

20-filter-start

```auto
filter {
  if "metric" not in [tags] {
    # Capture the @timestamp for use in lag calculations.
    # Capture the current time in nanos for use in filter timing.
    # Assign future and past limits (in seconds) for events.
    # Events that fall outside these limits are discarded.
    ruby {
      code => "
        event.set('[@metadata][elk_rcvd]', event.get('@timestamp'));
        event.set('[@metadata][elk_lag_future]', 86400.0);
        event.set('[@metadata][elk_lag_past]', 604800.0);
      "
    }
  }
}

```

21-filter-service-json

```auto
filter {
  if [type] == "service-json" {

    # Pull the embedded json fields up to the top level.
    json { source => "message" }

    # Convert and trim
    mutate {
      # Mark for output to elasticsearch
      add_field => { "[@metadata][elastic_output]" => true }
      add_field => { "[@metadata][elastic_index]" => "service" }

      # Rename some common fields to their indexed names.
      rename => {
        "request:header:x-site" => "site_id"
        "request:header:x-trace" => "trace_id"
        "request:header:x-reqname" => "requestor_id"
        "request:header:x-reqhost" => "requestor_host"
      }

      # Coerce some popular fields that are known to have inconsistencies
      convert => {
        "site_id" => "string"
        "shard_id" => "string"
      }
    }
  }
}

```

29-filter-stop

```auto
filter {
  # Only collect metrics for items that are heading to elasticsearch
  # This will filter out anything else (e.g. metrics) that are in the pipeline.
  if [@metadata][elastic_output] {
    # Calculate ingestion lag
    ruby {
      code => "
        event.set('elk_lag', event.get('[@metadata][elk_rcvd]') - event.get('@timestamp'));
        event.set('[@metadata][elk_lag_future]', -1 * event.get('[@metadata][elk_lag_future]'));
      "
    }

    # Drop events > elk_lag_future seconds in the future
    # Drop events > elk_lag_past seconds in the past
    if [elk_lag] {
      if [elk_lag] < [@metadata][elk_lag_future] {
        drop {}
      }
      if [elk_lag] > [@metadata][elk_lag_past] {
        drop {}
      }
    }

    # Rates by input type, output index
    metrics {
      meter => "type.%{type}"
      meter => "index.%{[@metadata][elastic_index]}"
      clear_interval => 60
      flush_interval => 60
      rates => [1,5]

      # Mark emit event for output to graphite
      add_field => { "[@metadata][graphite_output]" => true }
      add_field => { "[@metadata][graphite_index]" => "logstash" }
    }
  }
}

```

30-output-elastic

```auto
  # Only include events with the "elasticsearch" tag
  # Filters that interpret incoming logs should add this tag explcitly.
  # This will help keep stray events (e.g. metrics) from being indexed in
  # ElasticSearch.
  if [@metadata][elastic_output] {

    if [@metadata][audit_data] {
      elasticsearch {
        hosts => ['es-001','es-002','es-003']
        flush_size => 4096
        index => "audit-%{+YYYY.MM}"
        manage_template => false
      }

      elasticsearch {
        hosts => ['es-001','es-002','es-003']
        flush_size => 4096
        index => "infrastructure-%{+YYYY.MM.dd}"
        manage_template => false
      }
    } else {

      elasticsearch {
        hosts => ['es-001','es-002','es-003']
        flush_size => 4096
        index => "%{[@metadata][elastic_index]}-%{+YYYY.MM.dd}"
        manage_template => false
      }
    }
  }
}

```

---

<div class="post-metadata">

**Author:** ![DDEFISHER](https://avatars.discourse-cdn.com/v4/letter/d/b9e5f3/32.png) [@DDEFISHER](https://discuss.elastic.co/u/DDEFISHER)\
**Post date:** [March 22, 2018, 1:02pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/7 "2018-03-22T13:02:17Z")

</div>

Are these symptoms the same that would be caused by inode reuse? The thing is they happen a couple of times per day with log rotation set at every hour which seems to high to be inode reuse.

> On Linux file systems, Filebeat uses the inode and device to identify files. When a file is removed from disk, the inode may be assigned to a new file. In use cases involving file rotation, if an old file is removed and a new one is created immediately afterwards, the new file may have the exact same inode as the file that was removed. In this case, Filebeat assumes that the new file is the same as the old and tries to continue reading at the old position, which is not correct.

> By default states are never removed from the registry file. To resolve the inode reuse issue, we recommend that you use the clean\_\* options, especially clean\_inactive, to remove the state of inactive files. For example, if your files get rotated every 24 hours, and the rotated files are not updated anymore, you can set ignore\_older to 48 hours and clean\_inactive to 72 hours.

> You can use clean\_removed for files that are removed from disk. Be aware that clean\_removed cleans the file state from the registry whenever a file cannot be found during a scan. If the file shows up again later, it will be sent again from scratch.

```auto

```

---

<div class="post-metadata">

**Author:** ![andrewkroh](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/andrewkroh/32/3784_2.png) [@andrewkroh](https://discuss.elastic.co/u/andrewkroh)\
**Post date:** [March 22, 2018, 1:43pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/8 "2018-03-22T13:43:49Z")

</div>

> [@DDEFISHER](#):
>
> Are these symptoms the same that would be caused by inode reuse?

If it is inode reuse I would expect to see Filebeat "resuming" on your new files from a much higher offset such that you lose a lot more than "first couple(could be alot) of new\_log". I think that if you enable debug logging for the `prospector` and `harvester`selectors you should be able to prove or disprove the theory based on [this log line](https://github.com/elastic/beats/blob/v5.6.3/filebeat/prospector/prospector_log.go#L245).

```auto
logging.level: debug
logging.selectors: [prospector, harvester]
```

---

<div class="post-metadata">

**Author:** ![DDEFISHER](https://avatars.discourse-cdn.com/v4/letter/d/b9e5f3/32.png) [@DDEFISHER](https://discuss.elastic.co/u/DDEFISHER)\
**Post date:** [March 22, 2018, 3:49pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/9 "2018-03-22T15:49:35Z")

</div>

Using the file output method you suggested it does look like it's a filebeat issue. This is the first message that filebeat picked up after a log rotation happened. The logline is split as you can see by the message. The actual logline is correct json.

```auto
{
  "@timestamp": "2018-03-22T15:30:04.900Z",
  "beat": {
    "hostname": "frodo-stg-002",
    "name": "frodo-stg-002",
    "version": "5.1.1"
  },
  "input_type": "log",
  "message": "ityDeleteAction.execute(EntityDeleteAction.java:114)\\n\\tat org.hibernate.engine.spi.ActionQueue.executeAct ions(ActionQueue.java:463)\\n\\tat org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:349)\\n\\tat org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350)\\n\\tat org.hibernate.event.intern al.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56)\\n\\tat org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1222)\\n\\tat org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:425)\\n\\tat org.hibernate.engine.transaction.inter nal.jdbc.JdbcTransaction.beforeTransactionCommit(JdbcTransaction.java:101)\\n\\tat org.hibernate.engine.transaction.spi.AbstractTransactionImpl.commit(AbstractTransactionImpl.java:177)\\n\\tat org.springframework.orm.hibernate4.HibernateTransactionManager.doCommit(Hib ernateTransactionManager.java:584)\\n\\t... 35 common frames omitted\\n\",\"service\":\"frodo\"}",
  "offset": 13416,
  "source": "/usr/local/frodo/log/service-logstash.log",
  "type": "service-json"
}

```

---

<div class="post-metadata">

**Author:** ![andrewkroh](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/andrewkroh/32/3784_2.png) [@andrewkroh](https://discuss.elastic.co/u/andrewkroh)\
**Post date:** [March 22, 2018, 3:56pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/10 "2018-03-22T15:56:15Z")

</div>

> [@DDEFISHER](#):
>
> "version": "5.1.1"

> [@DDEFISHER](#):
>
> File beat version: 5.6.3

You said Filebeat 5.6.3, but the data says 5.1.1. It would be good to try running the latest version.

---

<div class="post-metadata">

**Author:** ![DDEFISHER](https://avatars.discourse-cdn.com/v4/letter/d/b9e5f3/32.png) [@DDEFISHER](https://discuss.elastic.co/u/DDEFISHER)\
**Post date:** [March 22, 2018, 4:02pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/11 "2018-03-22T16:02:48Z")

</div>

This also happens on hosts with filebeat 5.6.6 but I will try to get a message that states that.

```auto
/usr/share/filebeat/bin/filebeat --version
filebeat version 5.6.6 (amd64), libbeat 5.6.6

```

---

<div class="post-metadata">

**Author:** ![andrewkroh](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/andrewkroh/32/3784_2.png) [@andrewkroh](https://discuss.elastic.co/u/andrewkroh)\
**Post date:** [March 22, 2018, 4:31pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/12 "2018-03-22T16:31:10Z")

</div>

With debug enabled, in the logs are you seeing

`Start harvester for new file: /usr/local/frodo/log/service-logstash.log`

when rotation occurs? Or are you seeing something like

`"Update existing file for harvesting: /usr/local/frodo/log/service-logstash.log, offset: <offset>`?

---

<div class="post-metadata">

**Author:** ![DDEFISHER](https://avatars.discourse-cdn.com/v4/letter/d/b9e5f3/32.png) [@DDEFISHER](https://discuss.elastic.co/u/DDEFISHER)\
**Post date:** [March 22, 2018, 4:33pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/13 "2018-03-22T16:33:49Z")

</div>

Yes and it seemed off to me that the first occurrence of it is even though filebeat was restarted for this test shortly after the log was rotated.

```auto
Update existing file for harvesting: /usr/local/frodo/log/service-logstash.log, offset: 23099

```

---

<div class="post-metadata">

**Author:** ![andrewkroh](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/andrewkroh/32/3784_2.png) [@andrewkroh](https://discuss.elastic.co/u/andrewkroh)\
**Post date:** [March 22, 2018, 4:44pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/14 "2018-03-22T16:44:54Z")

</div>

Seems like an inode reuse issue. Try deploying the options from [https://www.elastic.co/guide/en/beats/filebeat/5.6/faq.html#inode-reuse-issue](https://www.elastic.co/guide/en/beats/filebeat/5.6/faq.html#inode-reuse-issue).

---

<div class="post-metadata">

**Author:** ![DDEFISHER](https://avatars.discourse-cdn.com/v4/letter/d/b9e5f3/32.png) [@DDEFISHER](https://discuss.elastic.co/u/DDEFISHER)\
**Post date:** [March 23, 2018, 4:14pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/15 "2018-03-23T16:14:22Z")

</div>

Thanks for your help! I will try that and let you know if it solves the issue.

---

<div class="post-metadata">

**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\
**Post date:** [April 20, 2018, 4:15pm UTC](https://discuss.elastic.co/t/dropping-log-lines-on-log-rotation/125036/16 "2018-04-20T16:15:13Z")

</div>

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