How should output-elasticsearch deal with a missing @timestamp?

[webmat]

Events without @timestamp can be difficult to process in certain situations. According to code that dates back to 2013 (and probably before), its presence should be guaranteed. Logstash has never enforced this by preventing the removal of @timestamp per se, however.

So whenever a problem arises from a missing @timestamp, people may simply see an innocuous error like the following, and conclude that there's a bug in Logstash:

[2018-02-22T13:49:42,425][FATAL][logstash.runner ] An unexpected error occurred! {:error=>#<LogStash::Error: timestamp field is missing>, :backtrace=>["org/logstash/ext/JrubyEventExtLibrary.java:205:in sprintf'", "/Users/Gabriel/Documents/ElasticSearch/logstash-5.6.2/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-7.4.0-java/lib/logstash/outputs/elasticsearch/common.rb:169:inevent_action_params'", "/Users/Gabriel/Documents/ElasticSearch/logstash-5.6.2/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-7.4.0-java/lib/logstash/outputs/elasticsearch/common.rb:44:in event_action_tuple'", "/Users/Gabriel/Documents/ElasticSearch/logstash-5.6.2/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-7.4.0-java/lib/logstash/outputs/elasticsearch/common.rb:38:inmulti_receive'", "org/jruby/RubyArray.java:2414:in map'", "/Users/Gabriel/Documents/ElasticSearch/logstash-5.6.2/vendor/bundle/jruby/1.9/gems/logstash-output-elasticsearch-7.4.0-java/lib/logstash/outputs/elasticsearch/common.rb:38:inmulti_receive'", "/Users/Gabriel/Documents/ElasticSearch/logstash-5.6.2/logstash-core/lib/logstash/output_delegator_strategies/shared.rb:13:in multi_receive'", "/Users/Gabriel/Documents/ElasticSearch/logstash-5.6.2/logstash-core/lib/logstash/output_delegator.rb:49:inmulti_receive'", "/Users/Gabriel/Documents/ElasticSearch/logstash-5.6.2/logstash-core/lib/logstash/pipeline.rb:436:in output_batch'", "org/jruby/RubyHash.java:1342:ineach'", "/Users/Gabriel/Documents/ElasticSearch/logstash-5.6.2/logstash-core/lib/logstash/pipeline.rb:435:in output_batch'", "/Users/Gabriel/Documents/ElasticSearch/logstash-5.6.2/logstash-core/lib/logstash/pipeline.rb:381:inworker_loop'", "/Users/Gabriel/Documents/ElasticSearch/logstash-5.6.2/logstash-core/lib/logstash/pipeline.rb:342:in `start_workers'"]}```

One point of view about this is that the event should actually be considered invalid and whatever lead to this situation is likely to cause data loss.

There are two schools of thoughts or approaches we can take for these:

1. We can try to support these events as best as possible
2. We can take a hard line and not try to support these events, and assume that the customer's configuration has a problem that will lead to data loss. We can adjust the level of "severity" we take with this approach.

In either case, in order to prevent needless confusion and support requests, we should at the very least output a log message that's a bit more verbose than the one above, in explaining what the problem actually is. With this event it's missing @timestamp and the customer tries to index it to a timestamped index (like logstash-%{+YYYY.MM.dd}).

Are non-timestamped events legitimate?

The behaviour currently (unless the above situation happens) is to successfully index the event. I would argue there's a legitimate use case for removing @timestamp in Logstash pipelines. It's counterintuitive because Logstash was born to process time-based data. But once someone has a Logstash installation, Logstash is a great way to ingest non time-based data periodically to their ElasticSearch cluster.

Examples of non time-based data to reimport regularly:

• zip codes (or other regional databases)
• IP geolocation databases
• other kinds of CSV data dumps

Another supporting argument for the legitimacy of non time-based support in Logstash is the fact that our plugins are gradually getting better at supporting non time-sensitive scenarios:

• More explicit support in input-file for reading full files, rather than tailing them (CSV imports)
• We've had requests (#9) and attempts (filter-lrucache) at making filter-elasticsearch be able to cache static datasets in memory, to achieve a behaviour, similar to filter-jdbc_static. This is a sign that people have static datasets in ES.

The last point in demonstrating the legitimacy of processing non-timestamped data with Logstash is the very first Logstash configuration one sees, during the ElasticSearch training.

Here we're ingesting bunch of data, but we're not interested in keeping @timestamp (among others).

Approach 1: Support these events as best as possible

The current behaviour is that events with no @timestamps work in most cases. People can do this, and are doing it. There are still some improvements we can make:

• Output a more explicit message when someone tries to index an event without a @timestamp to a timestamped index.
  • Part of #777 was about putting in place this clearer messaging.
• Instead of a full Logstash crash (current behaviour), output an ERROR for every event in this situation, and keep Logstash running.
  • #777 implements this behaviour
• If the customer has DLQ enabled, we could even send the event there. Perhaps their timestamp is just named incorrectly and they may be able to reprocess these events without any other disruption.
  • One could argue that the DLQ may fill up before people notice this & so on, and they may lose data eventually.
  • Idea floated in some form in #718 and tracked as part of a bigger plan in #772

Approach 2: Interpret this as a problem with the user's configuration and crash

A lot of the feedback around #777 was not about the PR, but went in the direction that "not having a @timestamp on the event" was not officially supported. So this definitely stuck a chord with a few people :-)

In any case, nobody denies that we can improve the error message when the timestamp error happens.

Now, do we want to take a harder line to the effect that we do not want to support a missing @timestamp at all? If so, the current behaviour is not strict enough. We may want to take the following additional steps:

• Pre-emptively refuse any event without @timestamp as soon as we see them (whether or not the timestamp is needed).
• Eventually add a breaking change to Logstash, preventing the removal of @timestamp.
• Until this is prevented, should we always crash on any such event? (regardless of whether the event is problematic)

1+2=3: Let users decide

Any given user may really want Logstash to behave like 1, or to behave like 2. Presumably, the default could be the friendlier approach 1, and people who take great pains to construct a pipeline that has the least data loss possible (e.g. use only non-lossy transports & plugins, careful use of PQ & DLQ) could optionally decide that such events should indeed cause a hard crash.

Why this discussion?

This issue came out of the discussion here #777, which in turn came from reports such as #739. Requesting feedback on #777 in Slack immediately led to discussions of going towards approach #2.

[jsvd]

Just for reference, this issue happens because sprintf time interpolation behaves differently from normal interpolation:

2.3.0 :006 > e = LogStash::Event.new; e.sprintf("%{[hello]}")
 => "%{[hello]}" 
2.3.0 :007 > e = LogStash::Event.new; e.remove("@timestamp"); e.sprintf("%{+YYYY}")
LogStash::Error: timestamp field is missing
	from org/logstash/ext/JrubyEventExtLibrary.java:168:in `sprintf'
	from (irb):7:in `<eval>'

[webmat]

In case anyone is watching this issue, I just posted a massive update to the description of the issue. The focus is now solely on @timestamp, to keep the discussion focused on the problem at hand. Mentions of @version have been removed.

Also, I brought back my original approach to the matter on the table (trying to accommodate for the missing @timestamp). After initial feedback, I thought this approach was actually not gonna fly with anyone. But after the short discussion in the ingest meeting, I realized that I may not be alone in thinking that's a valid approach, after all :-)

[webmat]

In my mind, approaches 1 and 3 are tied as my favourites. I'd start with 1 because it's less work (it's essentially the current state + possible improvements), then if we want, we can continue working towards option 3.

My 3rd favourite approach is # 2, but I can live with it. However if we want to go the opinionated route, we'll have to be clear with our users that use cases removing @timestamp will no longer be accepted, and that this behaviour will be getting more severe with upcoming versions.

[andrewvc]

Thanks for the excellent writeup @webmat .

Whatever solution we come up with here, we should consider consistency with sprintf generically as @jsvd mentioned.

My suspicion here is that there is no one right answer here. What are your thoughts WRT creating two separate sprintf impls for plugins to use sprintf_strict and sprintf_lax, where sprintf_strict raises exceptions on missing fields (at which point it could be DLQed or whatever the author decides), while sprintf_lax always succeeds, but may include #{...}. This would mean that there would be consistency based on function call.

You'd use sprintf_strict for things like the ES index name interpolation, and sprintf_lax for everything else. We'd obsolete plain sprintf in a major.

[colinsurprenant]

Opposing concepts:

• @timestamp is a normal field in all respect (it can be removed) for the exception of having a specific construction & coercions behaviour : upon the creation of a new Event a @timestamp is always created so you can rely of the fact that all new Event always have a @timestamp.
• Some features and plugins expect a @timestamp to be present and consider @timestamp a special field. This is fine because @timestamp is usually central to most configurations.

Field removal

• We historically never wanted to force users with some permanent or non-removable fields. Users should be able to always shape the Event field the way they want without exception.
• In that respect I think this should also be true for @timestamp as it is now.
• The reason for removing a field is essentially for that field to not be present when serializing an Event "as a whole" typically at the outputs.

A proposal

• I believe we should keep the behaviour of being able to remove the @timestamp field so that it does not show up when either serializing (Event.toJson) or retrieving the event fields/values collection (Event.toMap, Event.getData) as intended when removing a field.

• I suggest we introduce a behavioral exception for the @timestamp field since it IS a special field in a way, for its behaviour at Event construction and also for its coercion behaviour. In fact internally the @timestamp value as its own class implementation.

  Removing @timestamp would work as intented BUT querying the field value from sprintf/interpolation and from field reference would always return its value regardless if was removed or not. This would allow users to shape the Event the way they want but would also never break features or plugins that rely on @timestamp to be present.

WDYT?

[andrewvc]

@colinsurprenant I agree that @timestamp should be removable.

I'm worried about that approach due to the amount of magic there, it seems like it violates the principle of least surprise if you can remove something but it still exists in some contexts.

What did you think of my proposal to let plugin authors decide what level of strictness was needed for interpolation on a case by case basis?

[colinsurprenant]

@andrewvc seems to add more complexity to me. OTOH what I propose is basically surfacing a fact that is true today which is that the timestamp has some special behaviour: we even have a Event.getTimestamp method. I thins this can be documented and for the principle of least surprise I think we could argue that my proposal does satisfy it since the intention is not to have the field appear in its serialized form which is the majority of cases where a field is removed and no change would be required in plugins.

It seems to me that conceptually it will be easy to explain and understand for the users that there is one special field in the Event and it has to do with the timestamp handling and the reason is because some features and plugins expect a timestamp to be present but regardless, this field does not need to be included in the event serialized form, by removing it.

[andrewvc]

@colinsurprenan That's a good point. I see that it does solve the problems you mention. It does have the cost of being yet another 'special' thing to document.

Here's a thought, what if we deprecate @timestamp and say that the canonical place for it is [@metadata][timestamp], which doesn't serialize by default. @metadata would then be the single place where you put data that doesn't serialize. Thoughts?

We'd also adjust sprintf for timestamps to treat that like an ordinary field.

[andrewvc]

To clarify what I mean by 'like an ordinary field', I mean that we'd follow the same interpolation rules. I do think we need a strict interpolation variant regardless of the timestamp decision to let plugin authors decide if interpolation issues are fatal.