16 ms·

I'm inclined to agree. Traditional logging has a number of problems. Developers tend to just stick `log.Info` (or whatever equivalent) anywhere. Using an htt

by chrsig 4y ago

I'm inclined to agree. Traditional logging has a number of problems. Developers tend to just stick `log.Info` (or whatever equivalent) anywhere. Using an http server as an example: The result is that one http request may produce dozens of log messages. But because multiple http requests are running at the same time, they all get interleaved in the actual log. They can be tied together after the fact if you're using a request id, but that requires post processing. It can be difficult to know when a request ends, so that means there needs to be an explicit "end of request" type message, otherwise assume that it could still be active until the end of the file...unless your log is rotating, in which case it could be in the next file, or the next. On top of that, it's a big performance hit. On every log message, you're serializing the message, acquiring a mutex, flushing it out to disk. Depending on the library, some of that may or may not get evaluated depending on message severity. It's a non-trivial overhead, and individual messages can cause quite a bit of contention for that mutex. Using something more like tracing, a log message gets attached to a context for the task, and it's not until the task is complete does anything get logged. This makes for a single log message that has a list of all the individual informational messages, as well as other metadata about the request. One mutex acquisition, one serialization, one file flush. It's at that point where tracing and logging are arguably the same thing.

KronisLV 4y ago
> It's at that point where tracing and logging are arguably the same thing. On some level I agree with this, but honestly tracing doesn't have nearly the same adoption that logging has (at least in my experience). Why? Because generally it's easier to approach logging, even if in ways that don't necessarily scale that well: like getting your application writing logs to a file on the server directory. Note: I mention Java here, but a lot of it also applies to Node/Python/Go/Ruby etc. Eventually they can be moved over to a networked share, have Logrotate running against them, or perhaps have proper log shipping in place. That is perhaps the hardest aspect, since for tracing (outside of something like JavaMelody which is integrated inside of your app) you'll also need to set up some sort of a platform for the logs to be shipped to and processed in any number of ways. Personally, I've found that something like Apache Skywalking is what many who want to look into it should consider, a setup utilizing which consists approximately of the following: - some sort of a database for it (ElasticSearch recommended, apparently PostgreSQL/MariaDB/MySQL viable) - the server application which will process data (can run as an OCI container) - the web application if you need an interface of this sort (can run as an OCI container) - an agent for your agent of choice, for example a set of .jar files for Java which can be setup with -javaagent - optionally, some JS for integrating with your web application (if that's what you're developing) Technically, you can also use Skywalking for log aggregation, but personally the setup isn't as great and their log view UI is a bit awkward (e.g. it's not easy to preview all logs for a particular service/instance in a file-like view), see the demo: https://skywalking.apache.org/ https://skywalking.apache.org/ For logs in particular, Graylog feels reasonably sane, since it has a similarly "manageable" amount of components, for a configuration example see: https://docs.graylog.org/docs/docker#settings https://docs.graylog.org/docs/docker#settings Contrast that to some of the more popular solutions out there, like Sentry, which gets way more complicated really quickly: https://github.com/getsentry/self-hosted/blob/master/docker-compose.yml https://github.com/getsentry/self-hosted/blob/master/docker-... For most of the people who have to deal with self-hosted setups where you might benefit from something like tracing or log shipping, actually getting the platform up and running will be an uphill battle, especially if not everyone sees the value in setting something like this up, or setting aside enough resources for it. Sometimes people will be more okay with having no idea why a system goes down randomly, rather than administering something like this constantly and learning new approaches, instead of just rotating a bunch of files. For others, there are no such worries, because they can open their wallets (without worrying about certain regulations and where their data can be stored, hopefully) and have some cloud provider give them a workable solution, so they just need to integrate their apps with some agent for shipping the information. For others yet, throwing the requirement over to some other team who's supposed to provide such platform components for them is also a possibility.
- phillipcarter 4y ago
  > Why? Because generally it's easier to approach logging That's due to a significant head start. When one practice has more than a decade to mature by spreading across an ecosystem and becoming more ergonomic, it's definitely going to be easier to adopt. However, tracing as come a LONG way with OpenTelemetry even in the past year. There's still a big mountain to climb, but making tracing better/more widespread and providing on-ramps to metrics and logging systems is exciting.
  - forrestthewoods 4y ago
    What’s the difference between logging and tracing?
    - phillipcarter 4y ago
      Logs come in two forms: structured and unstructured. Throw your unstructured logs in the garbage bin if you can - they do very little to help systematically analyze systems. Structured logs are logs that adhere to a schema and let you attach key:value pairs of additional metadata, so you can add context from your app to those logs. They're extremely helpful for systematically debugging systems, but they're not correlated with anything. With only logs, you need to divine what led to such a log yourself, or manually re-create tracing within your logging system. Traces are basically structured logs but have correlation IDs that let a backend stitch them together. Tracing libraries also offer a lot more than just this, but it's the core of tracing. I like to think that tracing is just an objectively better form of structured logging.
nine_k 4y ago
Logging to syslog already solves the problem of asynchronous / streamed logging. Structuring log messages better than an arbitrary text string is harder (even though I heard the widespread systemd offers a way). Mostly it's because it's hard to agree upon a universal standard. Logging in a self-describing structure is basically the same as logging in JSON (which is not unheard of). Maybe you could do a bit better logging in protobuf or thrift records.
- chrsig 4y ago
  Syslog doesn't solve any of the problems outlined above - you're just trading a file for a unix domain socket. And it introduces it's own problems, such as sharing that socket with the containers (if you just mount /dev/log into the container, you're gonna have a bad time when the syslog daemon restarts). Log rotation also becomes a problem at higher volumes. Want a 5 minute rotation? logrotate isn't of much help. re: logging in protobuf/thrift. Thrift is more well suited towards it due to it's stream friendliness. With protobufs, you can do better performance wise than json, but does tend to be a bit more annoying because you need to write a length header between messages. (at this point, I've considered logging directly into a `.tar` file with one file per request. I haven't ever done it, and wouldn't in production, but it's an intriguing thought to me.) With either format, you have to deal with the fact that they're now binary logs, and you lose out on the ability to use a number of tools like grep & awk, or you have some program to cat the log as plain text. Logging to json, while it's a bit more overhead, offers access to a lot of tooling which is lost with binary logging or unstructured logging. Athena, snowflake, sqlite, kafka/ksql, jq, it's incredibly ELK friendly...The list goes on. In general, it's usable without the message definitions, so it can be much easier to use. All of these tradeoffs wildly depend on what it is that you're logging and what your needs are.
  - aprdm 4y ago
    You can have syslog emit json
- r3trohack3r 4y ago
  > Mostly it's because it's hard to agree upon a universal standard This is one of the things I’ve appreciated in my corner of the Nodejs ecosystem. It’s fairly standardized around pino and bunyan. With async hooks you can instrument all downstream async APIs too and associate them with the incoming request. So, by default, in my services all logs are associated with their incoming requests. That being said - I’m inclined to agree that, as the distributed tracing ecosystem becomes increasingly mature, it really is eating the use case of logs. The real trick with tracing is being able to associate a spike in latency for 5xx requests in metrics with all their associated traces. With logs I can aggregate all 5xx logs, filter by latency, and get the subset of logs for the high latency requests to dig in. In more mature stacks, I can even conditionally increase log sampling on-demand for those requests to get a better view into the problem (especially helpful for rare events that are unlikely to make it past the sampler). I’m not good enough with traces yet to do this. Today I have to start with logs to find the request IDs to get to the traces.
wokkel 4y ago
Just look into log4j: mdc/ndc to include context (user/session), include the thread name in your pattern and use an async appender to take care of performance. All of these things have been solved already.
- chrsig 4y ago
  > All of these things have been solved already. I mean...yes, that's how I was able to highlight the benefits of having a single log message per request. > Just look into log4j: mdc/ndc to include context (user/session), include the thread name in your pattern and use an async appender to take care of performance. At a glance this looks like it will still produce 1 log line per logging call, versus buffering with the request. adding the thread id just helps stitch them together after the fact. This doesn't get rid of any performance overhead -- it may get it out of the way of a user request, but it's still there under the hood. In the go case, using the runtime/trace library as an example[0], a `context.Context` is passed down the call stack which gets decorated with trace spans/regions/log messages on the way down. At the end of a task, all of the collected context gets written to the active trace log. [0] https://pkg.go.dev/runtime/trace https://pkg.go.dev/runtime/trace
  - wokkel 4y ago
    I like my log to include where something happened and in some complex cases having a few thousand lines of logging info per request is not unreasonable. So stuffing al that info into a single log event/line doesn't make sense to me. I recently had the unfortunate situation where two seemingly independant sessions were interfering, here a sequential logfile where things were logged in the order occurring was the only way to correlate them. Even though we do telemetry via events, old school logfiles are a godsend to debug the complex cases.
- wsargent 4y ago
  MDC/NDC only reliably works when you don't have asynchronous code (Akka/Vert.x/CompletionStage) through your application. As soon as you start using multiple threads, it becomes significantly more complex to keep MDC context carried over from one thread to the next.
xani_ 4y ago
> Using something more like tracing, a log message gets attached to a context for the task, and it's not until the task is complete does anything get logged. This makes for a single log message that has a list of all the individual informational messages, as well as other metadata about the request. One mutex acquisition, one serialization, one file flush. That's kinda terrible design. You don't see anything in progress, only if it finishes, and anything in progress just disappears, never to be seen again, if app crashes. Splitting to event per action in a given context is a feature, not a bug
- jiggawatts 4y ago
  Not necessarily, this is an implementation detail. Azure Application Insights for example streams events to a log file asynchronously. A crash is typically captured as a memory snapshot crash dump anyway, so if the entire process terminates then you have something that's probably superior to a text log! If you open the crash dump, you can inspect the in-memory buffer of log events directly in a debugger. If the operation fails internally with an exception, then the logs are captured as normal including the exception details. Asynchronous logging is dramatically more efficient. Or to put it another way, synchronous logging often causes performance bottlenecks that surprises developers. If you do want "live" logs equivalent to viewing the tail of a text file, most systems (such as App Insights mentioned above) can dynamically switch from async to sync mode and stream all events second-by-second.
GeneralMayhem 4y ago
> But because multiple http requests are running at the same time, they all get interleaved in the actual log. Many logging libraries will export a structured preamble including the timestamp and PID, which is enough to reconstruct single-threaded time histories when you want them, while still allowing you to see cross-thread time-correlated issues when you need that as well.
- kitd 4y ago
  Unfortunately async code often blows that idea up. Cf. Node apps where the log comes from some arbitrary callback with little to no indication of where the root cause occurred.

by chrsig 4y ago

KronisLV 4y ago

> It's at that point where tracing and logging are arguably the same thing. On some level I agree with this, but honestly tracing doesn't have nearly the same adoption that logging has (at least in my experience). Why? Because generally it's easier to approach logging, even if in ways that don't necessarily scale that well: like getting your application writing logs to a file on the server directory. Note: I mention Java here, but a lot of it also applies to Node/Python/Go/Ruby etc. Eventually they can be moved over to a networked share, have Logrotate running against them, or perhaps have proper log shipping in place. That is perhaps the hardest aspect, since for tracing (outside of something like JavaMelody which is integrated inside of your app) you'll also need to set up some sort of a platform for the logs to be shipped to and processed in any number of ways. Personally, I've found that something like Apache Skywalking is what many who want to look into it should consider, a setup utilizing which consists approximately of the following: - some sort of a database for it (ElasticSearch recommended, apparently PostgreSQL/MariaDB/MySQL viable) - the server application which will process data (can run as an OCI container) - the web application if you need an interface of this sort (can run as an OCI container) - an agent for your agent of choice, for example a set of .jar files for Java which can be setup with -javaagent - optionally, some JS for integrating with your web application (if that's what you're developing) Technically, you can also use Skywalking for log aggregation, but personally the setup isn't as great and their log view UI is a bit awkward (e.g. it's not easy to preview all logs for a particular service/instance in a file-like view), see the demo: https://skywalking.apache.org/ https://skywalking.apache.org/ For logs in particular, Graylog feels reasonably sane, since it has a similarly "manageable" amount of components, for a configuration example see: https://docs.graylog.org/docs/docker#settings https://docs.graylog.org/docs/docker#settings Contrast that to some of the more popular solutions out there, like Sentry, which gets way more complicated really quickly: https://github.com/getsentry/self-hosted/blob/master/docker-compose.yml https://github.com/getsentry/self-hosted/blob/master/docker-... For most of the people who have to deal with self-hosted setups where you might benefit from something like tracing or log shipping, actually getting the platform up and running will be an uphill battle, especially if not everyone sees the value in setting something like this up, or setting aside enough resources for it. Sometimes people will be more okay with having no idea why a system goes down randomly, rather than administering something like this constantly and learning new approaches, instead of just rotating a bunch of files. For others, there are no such worries, because they can open their wallets (without worrying about certain regulations and where their data can be stored, hopefully) and have some cloud provider give them a workable solution, so they just need to integrate their apps with some agent for shipping the information. For others yet, throwing the requirement over to some other team who's supposed to provide such platform components for them is also a possibility.

phillipcarter 4y ago
> Why? Because generally it's easier to approach logging That's due to a significant head start. When one practice has more than a decade to mature by spreading across an ecosystem and becoming more ergonomic, it's definitely going to be easier to adopt. However, tracing as come a LONG way with OpenTelemetry even in the past year. There's still a big mountain to climb, but making tracing better/more widespread and providing on-ramps to metrics and logging systems is exciting.
- forrestthewoods 4y ago
  What’s the difference between logging and tracing?
  - phillipcarter 4y ago
    Logs come in two forms: structured and unstructured. Throw your unstructured logs in the garbage bin if you can - they do very little to help systematically analyze systems. Structured logs are logs that adhere to a schema and let you attach key:value pairs of additional metadata, so you can add context from your app to those logs. They're extremely helpful for systematically debugging systems, but they're not correlated with anything. With only logs, you need to divine what led to such a log yourself, or manually re-create tracing within your logging system. Traces are basically structured logs but have correlation IDs that let a backend stitch them together. Tracing libraries also offer a lot more than just this, but it's the core of tracing. I like to think that tracing is just an objectively better form of structured logging.

nine_k 4y ago

Logging to syslog already solves the problem of asynchronous / streamed logging. Structuring log messages better than an arbitrary text string is harder (even though I heard the widespread systemd offers a way). Mostly it's because it's hard to agree upon a universal standard. Logging in a self-describing structure is basically the same as logging in JSON (which is not unheard of). Maybe you could do a bit better logging in protobuf or thrift records.

chrsig 4y ago
Syslog doesn't solve any of the problems outlined above - you're just trading a file for a unix domain socket. And it introduces it's own problems, such as sharing that socket with the containers (if you just mount /dev/log into the container, you're gonna have a bad time when the syslog daemon restarts). Log rotation also becomes a problem at higher volumes. Want a 5 minute rotation? logrotate isn't of much help. re: logging in protobuf/thrift. Thrift is more well suited towards it due to it's stream friendliness. With protobufs, you can do better performance wise than json, but does tend to be a bit more annoying because you need to write a length header between messages. (at this point, I've considered logging directly into a `.tar` file with one file per request. I haven't ever done it, and wouldn't in production, but it's an intriguing thought to me.) With either format, you have to deal with the fact that they're now binary logs, and you lose out on the ability to use a number of tools like grep & awk, or you have some program to cat the log as plain text. Logging to json, while it's a bit more overhead, offers access to a lot of tooling which is lost with binary logging or unstructured logging. Athena, snowflake, sqlite, kafka/ksql, jq, it's incredibly ELK friendly...The list goes on. In general, it's usable without the message definitions, so it can be much easier to use. All of these tradeoffs wildly depend on what it is that you're logging and what your needs are.
- aprdm 4y ago
  You can have syslog emit json
r3trohack3r 4y ago
> Mostly it's because it's hard to agree upon a universal standard This is one of the things I’ve appreciated in my corner of the Nodejs ecosystem. It’s fairly standardized around pino and bunyan. With async hooks you can instrument all downstream async APIs too and associate them with the incoming request. So, by default, in my services all logs are associated with their incoming requests. That being said - I’m inclined to agree that, as the distributed tracing ecosystem becomes increasingly mature, it really is eating the use case of logs. The real trick with tracing is being able to associate a spike in latency for 5xx requests in metrics with all their associated traces. With logs I can aggregate all 5xx logs, filter by latency, and get the subset of logs for the high latency requests to dig in. In more mature stacks, I can even conditionally increase log sampling on-demand for those requests to get a better view into the problem (especially helpful for rare events that are unlikely to make it past the sampler). I’m not good enough with traces yet to do this. Today I have to start with logs to find the request IDs to get to the traces.

wokkel 4y ago

Just look into log4j: mdc/ndc to include context (user/session), include the thread name in your pattern and use an async appender to take care of performance. All of these things have been solved already.

chrsig 4y ago
> All of these things have been solved already. I mean...yes, that's how I was able to highlight the benefits of having a single log message per request. > Just look into log4j: mdc/ndc to include context (user/session), include the thread name in your pattern and use an async appender to take care of performance. At a glance this looks like it will still produce 1 log line per logging call, versus buffering with the request. adding the thread id just helps stitch them together after the fact. This doesn't get rid of any performance overhead -- it may get it out of the way of a user request, but it's still there under the hood. In the go case, using the runtime/trace library as an example[0], a `context.Context` is passed down the call stack which gets decorated with trace spans/regions/log messages on the way down. At the end of a task, all of the collected context gets written to the active trace log. [0] https://pkg.go.dev/runtime/trace https://pkg.go.dev/runtime/trace
- wokkel 4y ago
  I like my log to include where something happened and in some complex cases having a few thousand lines of logging info per request is not unreasonable. So stuffing al that info into a single log event/line doesn't make sense to me. I recently had the unfortunate situation where two seemingly independant sessions were interfering, here a sequential logfile where things were logged in the order occurring was the only way to correlate them. Even though we do telemetry via events, old school logfiles are a godsend to debug the complex cases.
wsargent 4y ago
MDC/NDC only reliably works when you don't have asynchronous code (Akka/Vert.x/CompletionStage) through your application. As soon as you start using multiple threads, it becomes significantly more complex to keep MDC context carried over from one thread to the next.

xani_ 4y ago

> Using something more like tracing, a log message gets attached to a context for the task, and it's not until the task is complete does anything get logged. This makes for a single log message that has a list of all the individual informational messages, as well as other metadata about the request. One mutex acquisition, one serialization, one file flush. That's kinda terrible design. You don't see anything in progress, only if it finishes, and anything in progress just disappears, never to be seen again, if app crashes. Splitting to event per action in a given context is a feature, not a bug

jiggawatts 4y ago
Not necessarily, this is an implementation detail. Azure Application Insights for example streams events to a log file asynchronously. A crash is typically captured as a memory snapshot crash dump anyway, so if the entire process terminates then you have something that's probably superior to a text log! If you open the crash dump, you can inspect the in-memory buffer of log events directly in a debugger. If the operation fails internally with an exception, then the logs are captured as normal including the exception details. Asynchronous logging is dramatically more efficient. Or to put it another way, synchronous logging often causes performance bottlenecks that surprises developers. If you do want "live" logs equivalent to viewing the tail of a text file, most systems (such as App Insights mentioned above) can dynamically switch from async to sync mode and stream all events second-by-second.

GeneralMayhem 4y ago

> But because multiple http requests are running at the same time, they all get interleaved in the actual log. Many logging libraries will export a structured preamble including the timestamp and PID, which is enough to reconstruct single-threaded time histories when you want them, while still allowing you to see cross-thread time-correlated issues when you need that as well.

kitd 4y ago
Unfortunately async code often blows that idea up. Cf. Node apps where the log comes from some arbitrary callback with little to no indication of where the root cause occurred.