Log lines out of order -- even when submitted IN ORDER about logplex

[freeformz]

I am sorry that this is frustrating for you, let me explain why this is:

There are effectively multiple processes behind each dyno, delivering logs to multiple logplex nodes. Logplex then forwards this data to drains / tail sessions in near real time.

For display purposes, receivers of drains should sort logs by the provided time stamp as that is preserved throughout the system on our side. This is how internal systems work.

For tails there isn't much we can do because there is no way to know that some logs just aren't late in getting through the system, so they are displayed in the received order (modulo system load and the like).

A little more background ....

Delivery from a dyno -> logplex is handled by https://github.com/heroku/log-shuttle, which spawns multiple go-routines for delivery. Even if there was a single goroutine delivering messages from a dyno, each batch of log messages may be load balanced to any logplex node in the cluster and there is no guarantee they would get to the drain/tail in the same order.

We can't pin a dyno to delivering to only a single logplex node, otherwise a hot app would negatively affect multiple customers who's apps are also sending through that logplex node. This was a severe problem before we switched to log-shuttle.

If we delayed logs by some time factor (say 10, 20 or 30s) we could guarantee order, but the complexity and cost of the system would go up significantly. And we would have to consider logs arriving after the deadline as lost or fall back to out of order delivery, leaving us in the same place we started.

Does that make sense as to why logs are out of order?

If you are using a log archiving service and viewing these logs there and they are still out of order, then that service is not ordering on the timestamp we supplied and is likely ordering on when they received the log message. I would urge you to ask them to offer an option to order on the provided timestamp.

[troy]

@freeformz This makes a lot of sense. Do you think there would be much improvement from load balancing the logplex connections with stickiness/persistence based on source IP, so at least messages from the same dyno generally hit the same logplex?

This might be impractical or impossible for a dozen other reasons that I don't know, so please don't consider it a suggestion, just something that came to mind. Even in the best case, stickiness would just reduce out-of-order delivery, not eliminate it (nor change the producer/consumer contract). Still, I could see it getting to the point where a typical receiver - or someone pointing logplex at their own rsyslog that's writing to a file in the order received - doesn't experience it often enough to care.

As a log destination, one challenge we run into is knowing when timestamps are reliable enough to be trusted. Even among users who reassure us over and over that their timestamps are accurate fleet-wide, I see cases all the time where the slightest bit of clock drift on one system/VM wrecks the whole thing (and in non-obvious ways, since the user thinks their clocks are perfect). I'm sure that's not the case with Heroku's logplex senders, but in a weird sense, their reliability is different from almost all other senders.

[niedfelj]

@freeformz Thanks for that detailed reply. It would be nice if that were somewhere on the Heroku site in the documentation on logging, as I've never been able to get/find a detailed response. And yes, I'm using a log archiving service (logentries), but they don't sort by timestamp. I've also tried Troy's service, Papertrail, and they also don't sort by timestamp. Is there a log archiving service that you know of that does?

[troy]

@niedfelj Heroku's devcenter entry covers this in at least a little detail:

It is up to the logplex user to sort the logs and provide the ordering required by their application, if any.

I think it could be more explicit that even within the same dyno, ordering is not only not guaranteed, for many types of concurrent dynos, it's fairly unlikely.

[niedfelj]

@troy Yes, I've seen that. We had a few tickets going back and forth at one point about this when I was trying out Papertrail. I like a technical explanation ;)

[freeformz]

@troy

Re: Stickyness

There are several problems with this, the main one in my mind is "hot apps" (that pesky highly concurrent apps) that can log 25k+ log lines / second from a single dyno. We want those spread as evenly as possible across the fleet so as to have as little impact on a single node as possible. When factoring in hashing algorithms and distributions, several hot apps could clump together causing problems for a single node. This is basically exactly what we saw with syslog and why we moved away from it as a transport internally.

But, I have been thinking about adding some logic to log-shuttle so that it starts off with a single connection to logplex and only creates more (up to some limit) as needed based on volume. I have not because this: a) makes log-shuttle more complex; b) may increase memory usage as it will likely buffer more vs flushing as fast as possible via http; c) errors in the algorithm could cause all sorts of issues.

Re: Timestamps

The timestamp issue is irrelevant when discussing the logs from a single dyno though as the time source for those logs will all be the same: the local machine.

I still urge you guys to provide an option, at least, for users so that they are able to sort by timestamp included in the log message. I would also like you guys to enable that option for all heroku addons by default, but understand why you wouldn't do that. ;-)

[freeformz]

@niedfelj

I do not specifically know of a log archiving add-on that offers any particular sorting. I actually kind of assumed it would be by the provided timestamp by default. We use splunk internally and they have the Splunk Storm service, which AFAIK accepts drains.

I'll talk to our product manager about queuing up some work to clarify/expand on the dev center docs around ordering.

Thanks!

[niedfelj]

@StephenHynes7 Do you know if you guys can sort by timestamp at Logentries?

[StephenHynes7]

@niedfelj Currently no. We timestamp log entries when we receive them so if they are out of order when we get them then they will appear out of order in the UI.

[troy]

@freeformz Thanks, the explanation helps.

I think for any log destination built for general-purpose use, a sender with truly trustworthy timestamps is going to be the exception. Among those exceptions, that the destination actually needs to honor them for consistent order (rather than that out-of-order input could happen but is an edge case) is going to put logplex in its own class of senders. You know Heroku's tradeoffs better than I do, but that's a pretty big design constraint to push on to destinations.

Here's one example of how out-of-order - effectively, backdated as of the time of receipt - logs changes destinations' design constraints. With an always-increasing authoritative timestamp, webhook/alert services can know they're seeing a complete sample for the period in question. When the authoritative timestamp may include unknown gaps, either webhooks/alerts generated from logs would need to be delayed for the max duration that the sender could buffer ("Okay, that window is now closed"), or webhooks would need to expect multiple invocations covering the same time window.

Basically everything that acts on logs has to take one of those approaches. Sometimes one or both approaches are all but impossible, like when a metric destination only supports a single data point for a given time window, or when a CLI needs to insert a line before 20 that have already been output to a user.

[niedfelj]

@troy I guess my confusion is centered around why Papertrail and some other log archiving services don't offer sorting of any kind on a definable field when doing searching? I understand the realtime constraints, but it does seem like there should be the ability later on to reorder. The general use case that I have is this: Trying to figure out what happened in some request, look it up in logs by the tagged logger request id and read through the queries/renders etc.

[troy]

@niedfelj Good question. The use case makes total sense. The problem is that "reorder" is a euphemism for "change the assumption of contiguous logs" -- the hard part isn't sorting, it's behavior.

If you're referring to sorting afterwards ("later on to reorder"), each of the possible ways to do that has significant tradeoffs:

• it's in the server or data store: okay, but the problems in my last comment come into play. If logs are going to be "reordered later," do alerts get the first view that may have gaps which will be filled in later, or the reordered view that's delayed long enough to not have gaps? If it's the possibly non-sequential one, how do they deal with it?
• it's in a log consumer: a client can only sort the data it receives, which is often going to be incomplete when the server/data store is not sorting by the same attribute. If incomplete data wasn't ugly enough, this sorting would need to be implemented separately in everything that acts on logs.

(For both, I'm ignoring a bunch of smaller implementation considerations because they're solvable with work. They'd all be specific to senders with trusted time and out-of-order delivery, though, and probably no impact or additional complexity for other situations.)

Finally, one could try to hack up a set of compromises. For example, a consumer might specify the server/data store sorting method, an extra time bounds to include, and possibly the sorting method that the client is going to use ("I need this range plus 2 minutes on either side[1], and I'm going to sort the results afterwards by this other attribute"). This would be hard to implement correctly, fairly client-specific, and any situations that these constraints couldn't handle automagically would become end user confusion -- "Am I actually seeing everything?"

This is essentially the set of options that a broker like Kafka exposes to its consumers (details - see "Topics and Logs"). In those cases, it's because consumers are expected to address all of these questions (and the publisher offers features like rewinding/history to simplify it), and because immutable ordering is still guaranteed within a given partition. The issues above don't go away, they're just a lot easier for a consumer to solve or design around.

Summarizing, the question isn't "Can a service sort logs?" it's "What happens when logs may be reordered (and possibly, when gaps may be filled in after logs have been acted upon)?"

[freeformz]

FWIW: There is no problem with these issues internally when using splunk, which does order searches by the log's timestamp by default. It is a known issue that logs will come in out-of-order and we'll only display the logs, sorted in timestamp order (the default) that we have, for a given search. If you think more come in after that, then you have to re-run your query for the same time period. There used to be periods where logs would come into splunk minutes late (because of hot spots), but we've solved those problems, at least partially, via methods discussed above, which increased out-of-order delivery from the same source.

FWIW #2: I've only ever asked that log providers sort search results in log timestamp order (or at least provide that as an option). If a log provider does a real-time stream or real-time UI then I would expect the order to be based on when the log was received.

Sorry if that wasn't clear previously.

[Taytay]

TL;DR:
@niedfelj: From my limited testing, it looks like Loggly parses Heroku timestamps by default, and lists log statements in their sorted order. Loggly is no longer a Heroku Add-on, but is trivial to configure as an https log sync. If my findings are correct, we will likely switch, but this state of affairs is surprising to me.

Details:
Neither PaperTrail nor LogEntries (the two logging add-on options) sort incoming logs by the Heroku timestamp. In fact, I was pointed here by LogEntries' support when they confirmed that they do not support sorting by the Heroku timestamp.

We first discovered this issue yesterday when tracking down a nasty bug whose diagnosis was particularly dependent upon exact ordering of log statements, and realized that neither LogEntries nor PaperTrail sorts logs by the Heroku timestamp. In our case, the lines from the same dyno were very out of order, requiring me to paste into a spreadsheet and sort them. The funny thing is, I've been using Heroku with LogEntries for months and never read through my logs in close enough detail to even notice this. It didn't occur to me that A) Heroku would be shipping logs out of order from the same dyno, or B) that officially approved logging addons would ignore the Heroku timestamp that Heroku requests providers respect.

Both are surprising on their own. But in combination, I was shocked, and was sure I was just missing a setting somewhere in our log service. I can see @troy's points with regards to the difficulties on the receiving end. I can also respect @freeformz' points with regards to the complexities on the sending end.
As the innocent Heroku consumer though, I'm caught in the middle. I expect logging to be abstracted away by Heroku and my addon, and simply expect to see my logs in order (if not streamed in order, certainly when sorted after the fact). I assumed that Heroku and the official addons would have collaborated to solve this issue somehow.

At the very least, I would expect a disclaimer like this in the logging documentation "We recommend that logging services sort log statements by timestamp. However, at this time, neither of the Logging addons do so, so you your logs will not necessarily be displayed in the same order they are emitted. For more information..." (I would personally go so far as to list the services that are known to respect the Heroku timestamps like Splunk, Loggly, etc). Perhaps it is already there, but I did not see it yesterday when I was reading through it.

Either way, I'm glad to know that this is a known issue, and I have sympathy for both sides.

[troy]

I think your concerns are valid. I'd temper them with 2 things:

1. The docs cover ordering here.
2. This is 1 of 5, maybe even 10 or 20, aspects of operating a log management service for Heroku apps. Order matters to some users but doesn't matter at all to others. Also, many (most?) dynos' logs are not affected by out-of-order delivery, let alone often enough for it to be a problem. I think this attribute feels special because, well, it's impacting you right now :-) There's no more (or less) justification for listing which services do or don't re-order logs than which services do or don't offer or make use of any other platform-level feature. From experience, I can say that this isn't in the top 5 things which trip people up when logging from Heroku.

[Taytay]

Those are good points Troy - thanks for the broader perspective! :)

I think I am running into something odder than most, in that the vast
majority of my logs from the same dyno are in fact out of order. If it was
occasional, or only an inter-dyno thing, I agree that wouldn't be as big of
an issue. But now that I know I'm in the minority, (I assumed it was like
this for everyone) it makes it obvious why I didn't see more chatter about
this out there, and tones down my systemic concern a few notches.

And you are totally right - this feels like a big deal mainly because it's
biting me at the moment. I agree it's given me a bit of perspective
blindness. Speaking of blindness, I didn't even see the documentation you
linked to! Thanks for that.

Cheers.

On Friday, September 18, 2015, Troy Davis [email protected] wrote:

I think your concerns are valid. I'd temper them with 2 things:

The docs cover ordering here
https://devcenter.heroku.com/articles/logging#log-message-ordering.
2.

This is 1 of 5, maybe even 10 or 20, aspects of operating a log
management service for Heroku apps. Order matters to some users but doesn't
matter at all to others. Also, many (most?) dynos' logs are not affected by
out-of-order delivery, let alone often enough for it to be a problem. I
think this attribute feels special because, well, it's impacting you right
now :-) There's no more (or less) justification for listing which services
do or don't re-order logs than which services do or don't offer or make use
of any other platform-level feature. From experience, I can say that this
isn't in the top 5 things which trip people up when logging from Heroku.

—
Reply to this email directly or view it on GitHub
https://github.com/heroku/logplex/issues/120#issuecomment-141479835.

[hheimbuerger]

You're not alone, Taytay!

We're not experiencing this on every single log line, but often enough to be an issue. We also evaluated Logentries and this problem was one of the reasons we didn't move forward with them.

So thanks a lot for your recommendation of Loggly, I'll certainly have a look!

[voidlock]

@Taytay and @hheimbuerger We recently kicked off a research project to discover if there are ways to improve log line ordering. I encourage you both to open a support ticket. I would recommend referencing this issue to help ensure your ticket is escalated to the appropriate team.

We would love to explore the particular cases you are describing as they will provide more concrete examples.