6 ms·

Most logging is insanity in action. Behold: 1.2.3.4 - - [08/Aug/2023:12:48:11 +0200] "GET /wp-config.php.bak HTTP/1.1" 404 196 "-" "Mozilla/5.0 (Windows NT

Most logging is insanity in action. Behold: 1.2.3.4 - - [08/Aug/2023:12:48:11 +0200] "GET /wp-config.php.bak HTTP/1.1" 404 196 "-" "Mozilla/5.0 (Windows NT 6.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2503.0 Safari/537.36" 1. Apache has a perfectly coherent and structured view of the situation: Host 1.2.3.4 made a GET request of this particular URL, with this particular UA, at this particular date. 2. Apache proceeds to shove all this into a string, destroying the structure, and probably some of the data (it likely knows the timestamp with >1s precision) 3. Then to do some sort of analysis we need to manually reverse this process: write some convoluted regex to match this kind of line, turn an IP address back into a number, turn a timestamp into a number, find the delimiters. We're now undoing the damage Apache did. Why!? 4. For extra fun this adds extra problems to deal with log rotation, log compression, newlines and special characters in fields, and so on. All kinds of problems that are ultimately unproductive to solve and get in the way of actual useful work. Logging should be structured by nature. I shouldn't be writing weird regexps. I should have every message structured from the start, where I can search by "ip_address is in 1.2.3/24", or "request == 'GET'", or such. Every bit of data should be logged in its pristine form with zero ambiguity, with its original type, and analyzable accordingly. I think systemd has the beginning of a good idea in here, in that you can actually do this if you care to, and can send arbitrary chunks of data (even binary) to the log if needed. People who complain about journald not logging in plaintext honestly baffle me, because come on, whose idea of fun is it to do log parsing? And why are we spending CPU cycles on converting timestamps to text and parsing them back?

ranting-moth 3y ago
You can customize the log format from Apache. I highly recommend it!
- dale_glass 3y ago
  And it luckily has a journald module, which actually can log some fields in a structured manner. But even that doesn't seem to go far enough according to the docs. Eg, maybe I want structured logging for the HTTP headers. No way to get that at present, as far as I can tell.
  - backendanon 3y ago
    Sounds like systemd stuff. Why deal with systemd. Use Apache customized logging as the parent comment suggested.
    - dale_glass 3y ago
      > Sounds like systemd stuff. Why deal with systemd. Because it's better. Because it logs stuff separated by field, doesn't have problems with unusual characters or newlines, supports cursors, deals internally with log rotation and compression, a whole bunch of cool stuff. > Use Apache customized logging as the parent comment suggested. That's exactly what I want to avoid, for reasons explained in my original comment.
    - justsomehnguy 3y ago
      Because if you know you need a third value from the logs with ID NNN then you would always receive the third value from NNN message and nothing else. And no regex and locales shenanigans.
ethbr0 3y ago
The problem with logging since time immemorial seems to be log producers throught about it as 'How do we put records from one SQL table into strings?' IMHO, that's not even the right mental model, because it assumes a constant schema. Log entries are more like types: the fields in one entry may look nothing like the next. The consequence of using the wrong model is its inevitable collapse into 'Shove everything custom we need into a single field that's somewhat appropriate'. In the base case that devolves into everything in a one line string. Yet even in structured systems you see the behavior in {use of boring, standard fields correctly} + {everything else in an 'error' or 'customdata' field}. Thankfully, some tools and ecosystems seem to have grokked this and moved forward. And honestly, it's mostly an ecosystem problem (producers and consumers), so really needs to be solved via more programmatic self-declaration of data structures.
- dale_glass 3y ago
  Yeah, logging doesn't fit well into a RDBMS because fields can change from one message to another. My imagined ideal logging model is logging two things: 1. A structured tree of data. With field names, types, and content in native format. 2. An end-user hint about which of those fields are of most interest to an user. This is used by a log viewer to generate something like a traditional log file by default. So an HTTP log entry might contain the entire HTTP request with all the headers and metadata, and the hint then says "Of this, the admin probably want to see timestamp, URL and status code". You get the convenience of paging visually through what looks like a traditional log, but also everything is available for easy analysis.
  - ethbr0 3y ago
    To me, GraphQL is a great base model for what logs should be. The producer declares all possible data. The consumer requests the specific data it wants, at runtime. Because fundamentally, there's a mismatch of knowledge. Log consumers won't inherently know everything that can be in logs. Ergo, modern API-style ecosystem models are probably better approaches.
    - 3y ago
hotpotamus 3y ago
Awhile back I had to move a MariaDB database that should have been tiny. When we actually went to look at it, it was over 400GB and obviously the first question was WTF. The developers had decided to log to a table which did make for really simple ways to query the logs, but caused us to have to get a bit creative in the migration (which was actually kind of fun in the end). I'm sure it's been done many times, but it's the first time I had run into it.
- collaborative 3y ago
  How far back were the logs going to?
  - hotpotamus 3y ago
    On the order of years - we also cleaned that up at some point.
- KronisLV 3y ago
  Ohh I've seen similar situations. I recall wanting to dump a complex shared dev database, to make it easier to test destructive migrations locally in a container with no risk (that particular DBMS didn't support transactional DDL all that well). The problems started when I realized that it was far too large to be feasible... until I discovered that about 80-90% of all data was log tables, which in my case I could just skip and export everything else instead. Now, the logging implementation there used the EAV pattern and got somewhat complicated after years of development and maintenance... however it was mostly okay (in addition to some traditional logging into files and logrotate). That said, personally I'd use either a specialized log aggregation solution, or at the very least would store logs in a completely separate data store, both for resiliency and security reasons.
thaumasiotes 3y ago
> I should have every message structured from the start, where I can search by "ip_address is in 1.2.3/24" You want your logs to be opaque binary data that requires a special-purpose viewer?
- dale_glass 3y ago
  ...Yes? I don't care what format it is, I care about solving problems. But also I want pristine data. I don't want to be parsing text timestamps to convert them to a number I can then finally use to filter out what happened last Saturday. I want the system to know it is indeed a timestamp, and to natively support date comparisons, and to then be able to output that timestamp in whatever format might be required, if that's needed. Like this: journalctl -S '2023-08-06 12:00' -u libvirtd See, I get what I want and I don't have to figure out where in /var/log it is, what's the timestamp formatted like, if it's compressed and with what. All that is nonsense that gets in the way of getting the actual work done. Or I can also do stuff like: journalctl _PID=3663 Isn't it nice that I don't have to recurse through /var/log, uncompress compressed archives, and take into account that some things don't actually write the PID into the log?
  - macNchz 3y ago
    That's great if everything you're running plays nice with journald or generates logs in the same structured format, but the problem I always run into with production systems is the mess of various formats coming out of each piece of a running app... I find myself just wanting a folder full of plain text files I can grep/cut/awk my way through, however imperfect that may be. At this point I've used many different proprietary web based cloud log viewer apps that are slow, glitchy, and each have their own special query syntax. Theoretically I can leverage them for super powerful queries against structured logs, but instead I find myself using different ones frequently enough that I never master the syntax and have to read through the docs to do silly basic searches.
    - dale_glass 3y ago
      All of the above is an automatic journald feature. If it logs to syslog, or it's a systemd unit that logs to stderr, journald will automatically add various fields like the PID, and log timestamps with microsecond precision. Logging natively with journald allows you to add custom fields on top.
jonhohle 3y ago
We had this at Amazon and I built it at Okta because it was confounding that the closest thing was pumping things to collectdb or some other service that would immediately disassociate data from it’s request context into silos or have to wade through unstructured splunk logs (I don’t know if splunk structured logs are viable now). It’s extremely satisfying to be able to query request metrics and aggregate on arbitrary nested attributes when dealing with active issues. It’s probably something I should write about. Even though the idea is not novel, it doesn’t seem to be well supported by any libraries that I’m aware of and causes an impedance mismatch with the ones I knew about several years ago (dropwizard metrics and it’s subsequent derivatives).
jonfw 3y ago
Our app writes json logs and we use a tool (logdna) to centrally query/display those logs, it's a great solution IMO

ranting-moth 3y ago

You can customize the log format from Apache. I highly recommend it!

dale_glass 3y ago
And it luckily has a journald module, which actually can log some fields in a structured manner. But even that doesn't seem to go far enough according to the docs. Eg, maybe I want structured logging for the HTTP headers. No way to get that at present, as far as I can tell.
- backendanon 3y ago
  Sounds like systemd stuff. Why deal with systemd. Use Apache customized logging as the parent comment suggested.
  - dale_glass 3y ago
    > Sounds like systemd stuff. Why deal with systemd. Because it's better. Because it logs stuff separated by field, doesn't have problems with unusual characters or newlines, supports cursors, deals internally with log rotation and compression, a whole bunch of cool stuff. > Use Apache customized logging as the parent comment suggested. That's exactly what I want to avoid, for reasons explained in my original comment.
  - justsomehnguy 3y ago
    Because if you know you need a third value from the logs with ID NNN then you would always receive the third value from NNN message and nothing else. And no regex and locales shenanigans.

ethbr0 3y ago

The problem with logging since time immemorial seems to be log producers throught about it as 'How do we put records from one SQL table into strings?' IMHO, that's not even the right mental model, because it assumes a constant schema. Log entries are more like types: the fields in one entry may look nothing like the next. The consequence of using the wrong model is its inevitable collapse into 'Shove everything custom we need into a single field that's somewhat appropriate'. In the base case that devolves into everything in a one line string. Yet even in structured systems you see the behavior in {use of boring, standard fields correctly} + {everything else in an 'error' or 'customdata' field}. Thankfully, some tools and ecosystems seem to have grokked this and moved forward. And honestly, it's mostly an ecosystem problem (producers and consumers), so really needs to be solved via more programmatic self-declaration of data structures.

dale_glass 3y ago
Yeah, logging doesn't fit well into a RDBMS because fields can change from one message to another. My imagined ideal logging model is logging two things: 1. A structured tree of data. With field names, types, and content in native format. 2. An end-user hint about which of those fields are of most interest to an user. This is used by a log viewer to generate something like a traditional log file by default. So an HTTP log entry might contain the entire HTTP request with all the headers and metadata, and the hint then says "Of this, the admin probably want to see timestamp, URL and status code". You get the convenience of paging visually through what looks like a traditional log, but also everything is available for easy analysis.
- ethbr0 3y ago
  To me, GraphQL is a great base model for what logs should be. The producer declares all possible data. The consumer requests the specific data it wants, at runtime. Because fundamentally, there's a mismatch of knowledge. Log consumers won't inherently know everything that can be in logs. Ergo, modern API-style ecosystem models are probably better approaches.
  - 3y ago

hotpotamus 3y ago

Awhile back I had to move a MariaDB database that should have been tiny. When we actually went to look at it, it was over 400GB and obviously the first question was WTF. The developers had decided to log to a table which did make for really simple ways to query the logs, but caused us to have to get a bit creative in the migration (which was actually kind of fun in the end). I'm sure it's been done many times, but it's the first time I had run into it.

collaborative 3y ago
How far back were the logs going to?
- hotpotamus 3y ago
  On the order of years - we also cleaned that up at some point.
KronisLV 3y ago
Ohh I've seen similar situations. I recall wanting to dump a complex shared dev database, to make it easier to test destructive migrations locally in a container with no risk (that particular DBMS didn't support transactional DDL all that well). The problems started when I realized that it was far too large to be feasible... until I discovered that about 80-90% of all data was log tables, which in my case I could just skip and export everything else instead. Now, the logging implementation there used the EAV pattern and got somewhat complicated after years of development and maintenance... however it was mostly okay (in addition to some traditional logging into files and logrotate). That said, personally I'd use either a specialized log aggregation solution, or at the very least would store logs in a completely separate data store, both for resiliency and security reasons.

thaumasiotes 3y ago

> I should have every message structured from the start, where I can search by "ip_address is in 1.2.3/24" You want your logs to be opaque binary data that requires a special-purpose viewer?

dale_glass 3y ago
...Yes? I don't care what format it is, I care about solving problems. But also I want pristine data. I don't want to be parsing text timestamps to convert them to a number I can then finally use to filter out what happened last Saturday. I want the system to know it is indeed a timestamp, and to natively support date comparisons, and to then be able to output that timestamp in whatever format might be required, if that's needed. Like this: journalctl -S '2023-08-06 12:00' -u libvirtd See, I get what I want and I don't have to figure out where in /var/log it is, what's the timestamp formatted like, if it's compressed and with what. All that is nonsense that gets in the way of getting the actual work done. Or I can also do stuff like: journalctl _PID=3663 Isn't it nice that I don't have to recurse through /var/log, uncompress compressed archives, and take into account that some things don't actually write the PID into the log?
- macNchz 3y ago
  That's great if everything you're running plays nice with journald or generates logs in the same structured format, but the problem I always run into with production systems is the mess of various formats coming out of each piece of a running app... I find myself just wanting a folder full of plain text files I can grep/cut/awk my way through, however imperfect that may be. At this point I've used many different proprietary web based cloud log viewer apps that are slow, glitchy, and each have their own special query syntax. Theoretically I can leverage them for super powerful queries against structured logs, but instead I find myself using different ones frequently enough that I never master the syntax and have to read through the docs to do silly basic searches.
  - dale_glass 3y ago
    All of the above is an automatic journald feature. If it logs to syslog, or it's a systemd unit that logs to stderr, journald will automatically add various fields like the PID, and log timestamps with microsecond precision. Logging natively with journald allows you to add custom fields on top.

jonhohle 3y ago

We had this at Amazon and I built it at Okta because it was confounding that the closest thing was pumping things to collectdb or some other service that would immediately disassociate data from it’s request context into silos or have to wade through unstructured splunk logs (I don’t know if splunk structured logs are viable now). It’s extremely satisfying to be able to query request metrics and aggregate on arbitrary nested attributes when dealing with active issues. It’s probably something I should write about. Even though the idea is not novel, it doesn’t seem to be well supported by any libraries that I’m aware of and causes an impedance mismatch with the ones I knew about several years ago (dropwizard metrics and it’s subsequent derivatives).

jonfw 3y ago

Our app writes json logs and we use a tool (logdna) to centrally query/display those logs, it's a great solution IMO