Comments (18)
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.
from logplex.
@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.
from logplex.
@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?
from logplex.
@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.
from logplex.
@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 ;)
from logplex.
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. ;-)
from logplex.
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!
from logplex.
@StephenHynes7 Do you know if you guys can sort by timestamp at Logentries?
from logplex.
@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.
from logplex.
@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.
from logplex.
@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.
from logplex.
@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)?"
from logplex.
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.
from logplex.
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.
from logplex.
I think your concerns are valid. I'd temper them with 2 things:
- The docs cover ordering here.
- 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.
from logplex.
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.
from logplex.
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!
from logplex.
@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.
from logplex.
Related Issues (20)
- Error L10 - No new line after msg drop log HOT 2
- POST /sessions should respect false/null `tail` param HOT 1
- POST /v2/sessions channel_id type inconsistency HOT 1
- Logplex User Agent is Logplex/unknown
- Expiring redis spool key deletes channel from ets HOT 3
- Question: How to best deal with an app that produces too many logs? HOT 1
- Syslog messages are missing a NILVALUE for the STRUCTURED-DATA field. HOT 2
- Are Syslog UDP Drains Fully Supported? HOT 1
- logplex_api_v3_SUITE / fetch_channel_logs test flake
- drain inconsistencies?
- /v3/channels/:id/logs endpoint: unable to parse log buffers
- Replace OS env var caching with stillir. HOT 1
- Passing a tail parameter to /v2/sessions always tails, regardless of the value HOT 5
- Push failed: Could not get a logplex token for this app HOT 1
- Does not support Redis 2.8.x HOT 6
- Fail to reconnect to redis on timeout HOT 1
- Add CORS Support HOT 2
- why aren't the ports open? HOT 11
- failed_to_start_child, logplex_shard HOT 2
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from logplex.