6 ms·
Synchronous logging strikes again! We ran into this some at work with GLOG (Google's logging library), which can, e.g., block on disk IO if stdout is a file or
by loeg 3y ago
Synchronous logging strikes again! We ran into this some at work with GLOG (Google's logging library), which can, e.g., block on disk IO if stdout is a file or whatever. GLOG was like, 90-99% of culprits when our service stalled for over 100ms.
- cduzz 3y agoI have discussions with cow-orkers around logging; "We have Best-Effort and Guaranteed-Delivery APIs" "I want Guaranteed Delivery!!!" "If the GD logging interface is offline or slow, you'll take downtime; is that okay?" "NO NO Must not take downtime!" "If you need it logged, and can't log it, what do you do?" These days I just point to the CAP theorem and suggest that logging is the same as any other distributed system. Because there's a wikipedia article with a triangle and the word "theorem" people seem to accept that. [edit: added "GD" to clarify that I was referring to the guaranteed delivery logging api, not the best effort logging API]
- loeg 3y agoI read GD as “god damn,” which also seems to fit.
- rezonant 3y agoaw you beat me to it
- msm_ 3y agoInteresting, I'd think logging is one of the clearest situations when you want best effort. Logging is, almost by definition, not the "core" of your application, so failure to log properly should not prevent the core of the program from working. Killing the whole program because logging server is clearly throwing the baby out with the bathwater. What people probably mean is "logging is important, let's avoid losing log messages if possible", which is what "best" in "best effort" stands for. For example it's often a good idea to have a local log queue, to avoid data loss in case of a temporary log server downtime.
- cduzz 3y agoPeople use logging (appropriately or inappropriately; not my bucket of monkeys) for a variety of things including audit and billing records, which are likely a good case for a guaranteed delivery API. People often don't think precisely about what they say or want, and also often don't think through corner cases such as "what if XYZ breaks or gets slow?" And don't get me started on "log" messages that are 300mb events. Per log. Sigh.
- insanitybit 3y agoIf you lose logs when your service crashes you're losing logs at the time they are most important.
- _w1tm 3y agoNo, you’re losing client logs when your logging service crashes. Your logging service should probably not be logging through calls to itself.
- tux1968 3y agoThat's unavoidable if the logging service is down when your server crashes. Having a local queue doesn't mean logging to the service is delayed, it can be sent immediately. All the local queue does is give you some resiliency, by being able to retry if the first logging attempt fails.
- insanitybit 3y agoIf your logging service is down all bets are off. But by buffering logs you're now accepting that problems not related to the logging service will also cause you to drop logs - as I mentioned, your service crashing, or being OOM'd, would be one example.
- tux1968 3y agoWhat's more likely? An intermittent network issue, the logging service being momentarily down, or a local crash that only affects your buffering queue? If an OOM happens, all bets are off anyway, since it has as much likelihood of taking out your application as it does your buffering code. The local buffering code might very well be part of the application in the first place, so the fate of the buffering code is the same as the application anyway. It seems you're trying very hard to contrive a situation where doing nothing is better than taking reasonable steps to counter occasional network hiccups.
- supriyo-biswas 3y agoThe better way to do this is to write the logs to a file or an in-memory ring buffer and have a separate thread/process push logs from the file/ring-buffer to the logging service, allowing for retries if the logging service is down or slow (for moderately short values of down/slow). Promtail[1] can do this if you're using Loki for logging. [1] https://grafana.com/docs/loki/latest/send-data/promtail/ https://grafana.com/docs/loki/latest/send-data/promtail/
- insanitybit 3y agoBut that's still not guaranteed delivery. You're doing what the OP presented - choosing to drop logs under some circumstances when the system is down. a) If your service crashes and it's in-memory, you lose logs b) If your service can't push logs off (upstream service is down or slow) you either drop logs, run out of memory, or block
- hgfghui7 3y agoYou are thinking too much in terms of the stated requirements instead of what people actually want: good uptime and good debugability. Falling back to local logging means a blip in logging availability doesn't turn into all hands on deck everything is on fire. And it means that logs will very likely be available for any failures. In other words it's good enough.
- mort96 3y ago"Good uptime and good reliability but no guarantees" is just a good best effort system.
- insanitybit 3y agoGood enough is literally "best effort delivery", you're just agreeing with them that this is ultimately a distributed systems problem and you either choose CP or AP.
- kbenson 3y agoYeah, what the "best effort" actually means in practice is usually a result of how much resources you want to throw at the problem. Those give you runway on how much of a problem you can withstand and perhaps recover from without any loss of data (logs), but in the end you're usually still just buying time. That's usually enough though.
- rezonant 3y ago> "If the GD logging interface is offline or slow, you'll take downtime; is that okay?" > [edit: added "GD" to clarify that I was referring to the guaranteed delivery logging api, not the best effort logging API] i read GD as god-damned :-)
- salamanderman 3y agome too [EDIT: and I totally empathized]
- deleted 3y ago[deleted]
- deleted 3y ago[deleted]
- Zondartul 3y agoI have some wishfull thinking ideas on this, but it should be possible to have both at least in an imaginary, theoretical scenario. You can have both guaranteed delivery and no downtime if your whole system is so deterministic that anything that normally would result in blocking just will not, cannot happen. In other words it should be a hard real-time system that is formally verified top to bottom, down to the last transistor. Does anyone actually do that? Verify the program and the hardware to prove that it will never run out of memory for logs and such? Continuing this thought, logs are probably generated endlessly, so either whoever wants them has to also guarantee that that they are processedand disposed of right after being logged... or there is a finite ammount of log messages that can be stored (arbitrary number like 10 000) but the user (of logs) has to guarantee that they will take the "mail" out of the box sooner than it overfills (at some predictable, deterministic rate). So really that means even if OUR system is mathematically perfect, we're just making the downtime someone elses problem - namely, the consumer of the infinite logs. That, or we guarantee that the final resources of our self-contained, verified system will last longer than the finite shelf life of the system as a whole (like maybe 5 years for another arbitrary number)
- morelisp 3y agoPACELC says you get blocking or unavailability or inconsistency.
- ElectricalUnion 3y agoFrom a hardware point of view, this system is unlikely to exist, because you need a system with components that never have any reliability issues ever to have a totally deterministic system. From a software point of view, this system is unlikely to exist as it doesn't matter that the cause of your downtime is "something else that isn't our system". As a result, you're gonna end up requiring infinite reliable storage to upkeep your promises.
- tuetuopay 3y agoWe had prod halt once when the syslog server hanged. Logs were pushed through TCP which propagated the blocking to the whole of prod. We switched to UDP transport since: better to lose some logs than the whole of prod.
- tetha 3y agoEspecially if some system is unhappy enough to log enough volume to blow up the local log disk... you'll usually have enough messages and clues in the bazillion other messages that have been logged.
- deathanatos 3y agoTCP vs. UDP and async best-effort vs. synchronous are completely orthogonal… E.g., a service I wrote wrote logs to an ELK setup; we logged over TCP. But the logging was async: we didn't wait for logs to make it to ELK, and if the logging services went down, we just queued up logs locally. (To a point; at some point, the buffer fills up, and logs were discarded. The process would make a note of this if it happened, locally.)
- tuetuopay 3y ago> TCP vs. UDP and async best-effort vs. synchronous are completely orthogonal… I agree, when stuff is properly written. I don't remember the exact details, but at least with UDP the asyncness is built-in: there is no backpressure whatsoever. So poorly written software can just send udp to heart's end.
- lopkeny12ko 3y agoI would posit that if your product's availability hinges on +/- 100ms, you are doing something deeply wrong, and it's not your logging library's fault. Users are not going to care if a button press takes 100 more ms to complete.
- fnordpiglet 3y ago100ms for something like say API authorization on a high volume data plane service would be unacceptable. Exceeding latencies like that can degrade bandwidth and cause workers to exhaust connection counts. Likewise, even in humans response space, 100ms is an enormous part of a budget for responsiveness. Taking again authorization, if you spend 100ms, you’re exhausting the perceptible threshold for a humans sense of responsiveness to do something that’s of no practical value but is entirely necessary. Your UI developers will be literally camped outside your zoom room with virtual pitch forks night and day.
- loeg 3y agoYes, and in fact the service I am talking about is a high volume data plane service.
- hamandcheese 3y agoNot every API is a simple CRUD app with a user at the other end.
- kccqzy 3y agoAdd some fan out and 100ms could suddenly become 1s, 10s…
- saagarjha 3y agoCore libraries at, say, Google, are supposed to be reliable to several nines. If they go down for long enough for a human to notice, they’re failing SLA.
- loeg 3y agoOur service is expected to respond to small reads at under 1ms at the 99th percentile. >100ms stalls (which can go into many seconds) are absolutely unacceptable.
- oneepic 3y agoOh, we had this type of issue ("logging lib breaks everything") with a $MSFT logging library. Imagine having 100 threads each with their own logging buffer of 300MB. Needless to say it annihilated our memory and our server crashed, even on the most expensive sku of Azure App Service.
- pests 3y agoBrilliant strategy. Reminds me a litte of the oldtimers trick of adding a sleep(1000) somewhere so they could later come back and have some resources later, or if they needed a quick win with the client. Now cloud companies are using malloc(300000000) it to fake resource usage. /s
- RobertVDB 3y agoAh, the classic GLOG-induced service stall - brings back memories! I've seen similar scenarios where logging, meant to be a safety net, turns into a trap. Your 90-99% figure resonates with my experience. It's like opening a small window for fresh air and having a storm barrel in. We eventually had to balance between logging verbosity and system performance, kind of like a tightrope walk over a sea of unpredictable IO delays. Makes one appreciate the delicate art of designing logging systems that don't end up hogging the spotlight (and resources) themselves, doesn't it?
- deleted 3y ago[deleted]