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

[niedfelj]

I've been dealing with this issue for a long time on Heroku and it makes it almost impossible to read through my logs to track down issues. Why are log lines from 1 dyno and 1 thread/process that are created in order, spit out of the logplex in a different order? Somewhere there is something not buffering correctly. I understand that different dynos/processes might be interleaved in the logplex, but here is an example of a single request that I'm trying to follow and it's all over the place if you look at the timestamps. There is no buffering happening on my end (STDOUT.sync=true etc). It's very clear that Completed 200 OK is supposed to come at the end (based on timestamp). Why would it be interleaved in the middle?

2015-02-20T20:39:27.864570+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Started GET "/shop/fashion" for  at 2015-02-20 20:39:27 +0000
2015-02-20T20:39:27.908664+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   MOPED:   COMMAND      database=admin command={:ismaster=>1} runtime: 5.7000ms
2015-02-20T20:39:27.920864+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   MOPED:   COMMAND      database=admin command={:ismaster=>1} runtime: 8.7036ms
2015-02-20T20:39:27.926832+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] In overridden order controller helper /app/decorators/ /core_controller_helpers_order_decorator.rb
2015-02-20T20:39:27.992627+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]    ::Order Load (1.5ms)  SELECT  " _orders".* FROM " _orders"  WHERE " _orders"."user_id" = $1 AND " _orders"."completed_at" IS NULL  ORDER BY created_at DESC LIMIT 1  [["user_id", 2]]
2015-02-20T20:39:28.043291+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]    ::Store Load (1.0ms)  SELECT  " _stores".* FROM " _stores"  WHERE (url like '% %')  ORDER BY " _stores"."id" ASC LIMIT 1
2015-02-20T20:39:28.059925+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]    ::Order Load (1.4ms)  SELECT  " _orders".* FROM " _orders"  WHERE " _orders"."completed_at" IS NULL AND " _orders"."currency" = 'USD' AND " _orders"."guest_token" = 'emMw8Cbh87fN1lGOnmGHLw' AND " _orders"."store_id" = 1 AND " _orders"."user_id" = 2 LIMIT 1
2015-02-20T20:39:28.062099+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   CACHE (0.0ms)  SELECT " _line_items".* FROM " _line_items"  WHERE " _line_items"."order_id" IN (50703)  ORDER BY updated_at DESC
2015-02-20T20:39:27.887817+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Processing by ShopController#category as HTML
2015-02-20T20:39:27.887842+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Parameters: {"category"=>"fashion"}
2015-02-20T20:39:27.902959+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] MOPED: Creating new connection pool for <Moped::Node resolved_address="  ">
2015-02-20T20:39:27.912154+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] MOPED: Creating new connection pool for <Moped::Node resolved_address=" ">
2015-02-20T20:39:27.926272+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   MOPED:   QUERY        database= _cluster collection= _users selector={"$query"=>{"_id"=>BSON::ObjectId('5232282c75bda27c2b000008')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 3.0719ms
2015-02-20T20:39:27.935691+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]    ::User Load (1.6ms)  SELECT  " _users".* FROM " _users"  WHERE " _users"."deleted_at" IS NULL AND " _users"."id" = 2  ORDER BY " _users"."id" ASC LIMIT 1
2015-02-20T20:39:28.038534+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]    ::LineItem Load (1.0ms)  SELECT " _line_items".* FROM " _line_items"  WHERE " _line_items"."order_id" IN (50703)  ORDER BY updated_at DESC
2015-02-20T20:39:28.046638+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]    ::Store Load (1.2ms)  SELECT  " _stores".* FROM " _stores"  WHERE " _stores"."default" = 't'  ORDER BY " _stores"."id" ASC LIMIT 1
2015-02-20T20:39:28.061002+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   CACHE (0.0ms)  SELECT  " _orders".* FROM " _orders"  WHERE " _orders"."user_id" = $1 AND " _orders"."completed_at" IS NULL  ORDER BY created_at DESC LIMIT 1  [["user_id", 2]]
2015-02-20T20:39:28.066773+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]    ::Order Load (0.7ms)  SELECT " _orders".* FROM " _orders"  WHERE " _orders"."user_id" = $1 AND " _orders"."completed_at" IS NULL AND (id!=50703)  [["user_id", 2]]
2015-02-20T20:39:28.070422+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   MOPED:   QUERY        database= _cluster collection= _sites selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 2.0788ms
2015-02-20T20:39:28.194699+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   MOPED:   QUERY        database= _cluster collection= _contents selector={"$query"=>{"site_id"=>BSON::ObjectId('5230edc2e80e0f4508000002'), "state"=>"Finished", "publish_at"=>{"$lte"=>2015-02-20 20:39:28 UTC}, "expire_at"=>{"$not"=>{"$lte"=>2015-02-20 20:39:28 UTC}}, "categories"=>{"$all"=>[/^fashion$/i], "$size"=>1}, "$and"=>[{"_type"=>"ProductCategory"}]}, "$orderby"=>{"publish_at"=>-1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 121.9047ms
2015-02-20T20:39:28.216997+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   MOPED:   QUERY        database= _cluster collection= _contents selector={"$query"=>{"state"=>"Finished", "publish_at"=>{"$lte"=>2015-02-20 20:39:28 UTC}, "expire_at"=>{"$not"=>{"$lte"=>2015-02-20 20:39:28 UTC}}}, "$orderby"=>{"updated_at"=>-1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 3.3950ms
2015-02-20T20:39:28.236519+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Read fragment views/cache_buster-6fb6d83bd654ca6e6a5a16872755f4af/b4c36000694893544f1c51a2afc72661/b4c36000694893544f1c51a2afc72661 (15.7ms)
2015-02-20T20:39:28.243188+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered shared/_metas.html.erb (1.1ms)
2015-02-20T20:39:28.269094+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered shared/_analytics_top.html.erb (0.9ms)
2015-02-20T20:39:28.299775+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered content/_issue_provocation.html.erb (2.5ms)
2015-02-20T20:39:28.299893+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered shared/_branding.html.erb (20.9ms)
2015-02-20T20:39:28.348042+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   MOPED:   QUERY        database= _cluster collection= _contents selector={"$query"=>{"state"=>"Finished", "publish_at"=>{"$lte"=>2015-02-20 20:39:28 UTC}, "expire_at"=>{"$not"=>{"$lte"=>2015-02-20 20:39:28 UTC}}, "_type"=>{"$in"=>["Apartment"]}}, "$orderby"=>{"publish_at"=>-1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 36.1754ms
2015-02-20T20:39:28.363995+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered shared/_nav.html.erb (91.6ms)
2015-02-20T20:39:28.405038+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered email_subscribers/_form.html.erb (3.1ms)
2015-02-20T20:39:28.408777+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered shared/_share_modal.html.erb (1.1ms)
2015-02-20T20:39:28.414779+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered shared/_analytics_bottom.html.erb (3.4ms)
2015-02-20T20:39:28.416666+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Completed 200 OK in 529ms (Views: 141.8ms | ActiveRecord: 32.7ms | Mongoid: 207.3ms | Solr: 0.0ms)
2015-02-20T20:39:28.198823+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   MOPED:   QUERY        database= _cluster collection= _sites selector={"$query"=>{}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 2.0129ms
2015-02-20T20:39:28.217956+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Cache read: digestor/shop/category/html
2015-02-20T20:39:28.217997+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Cache generate: digestor/shop/category/html
2015-02-20T20:39:28.218024+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Cache write: digestor/shop/category/html
2015-02-20T20:39:28.220453+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Cache digest for shop/category.html: b4c36000694893544f1c51a2afc72661
2015-02-20T20:39:28.220477+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Cache write: digestor/shop/category/html
2015-02-20T20:39:28.220612+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Cache read: digestor/shop/category/html
2015-02-20T20:39:28.220656+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Cache fetch_hit: digestor/shop/category/html
2015-02-20T20:39:28.220842+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ] Cache read: views/cache_buster-6fb6d83bd654ca6e6a5a16872755f4af/b4c36000694893544f1c51a2afc72661/b4c36000694893544f1c51a2afc72661
2015-02-20T20:39:28.236926+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered shop/category.html.erb within layouts/application (28.1ms)
2015-02-20T20:39:28.264855+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]    (0.8ms)  SELECT COUNT(*) FROM " _roles" INNER JOIN " _roles_users" ON " _roles"."id" = " _roles_users"."role_id" WHERE " _roles_users"."user_id" = $1 AND " _roles"."name" = 'retail'  [["user_id", 2]]
2015-02-20T20:39:28.294360+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   MOPED:   QUERY        database= _cluster collection= _contents selector={"$query"=>{"state"=>"Finished", "publish_at"=>{"$lte"=>2015-02-20 20:39:28 UTC}, "expire_at"=>{"$not"=>{"$lte"=>2015-02-20 20:39:28 UTC}}, "_type"=>{"$in"=>["Volume"]}}, "$orderby"=>{"publish_at"=>-1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 13.4639ms
2015-02-20T20:39:28.360472+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   MOPED:   QUERY        database= _cluster collection= _contents selector={"$query"=>{"state"=>"Finished", "publish_at"=>{"$lte"=>2015-02-20 20:39:28 UTC}, "expire_at"=>{"$not"=>{"$lte"=>2015-02-20 20:39:28 UTC}}, "_type"=>{"$in"=>["SiteMessaging"]}}, "$orderby"=>{"publish_at"=>-1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 10.8335ms
2015-02-20T20:39:28.392157+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered email_subscribers/_form.html.erb (21.0ms)
2015-02-20T20:39:28.392266+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered shared/_footer.html.erb (25.5ms)
2015-02-20T20:39:28.397998+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered shared/_minicart_tmpl.html.erb (1.9ms)
2015-02-20T20:39:28.405182+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   Rendered email_subscribers/_newsletter_bottombanner.html.erb (4.1ms)
2015-02-20T20:39:28.414438+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   CACHE (0.0ms)  SELECT COUNT(*) FROM " _roles" INNER JOIN " _roles_users" ON " _roles"."id" = " _roles_users"."role_id" WHERE " _roles_users"."user_id" = $1 AND " _roles"."name" = 'retail'  [["user_id", 2]]
2015-02-20T20:39:28.415787+00:00 app[web.1]: [817f4b05-4d0a-4458-8226-ce66d72cdcba] [ ]   CACHE (0.0ms)  SELECT COUNT(*) FROM " _roles" INNER JOIN " _roles_users" ON " _roles"."id" = " _roles_users"."role_id" WHERE " _roles_users"."user_id" = $1 AND " _roles"."name" = 'retail'  [["user_id", 2]]

[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 notifications@github.com wrote:

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

1.

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!

[alexmarnell]

@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.