5 ms·

While I agree with some of it, I feel like there's a big gotcha here that isn't addressed. Having 1 single wide event, at the end of a request, means that if so

• wesammikhail 10mo ago
  The way I have solved for this in my own framework in PHP is by having a Logging class with the following interface interface LoggerInterface { // calls $this->system(LEVEL_ERROR, ...); public function exception(Throwable $e): void; // Typical system logs public function system(string $level, string $message, ?string $category = null, mixed ...$extra): void; // User specific logs that can be seen in the user's "my history" public function log(string $event, int|string|null $user_id = null, ?string $category = null, ?string $message = null, mixed ...$extra): void; } I also have a global exception handler that is registered at application bootstrap time that takes any exception that happens at runtime and runs $logger->exception($e); There is obviously a tiny bit more of boilerplating to this to ensure reliability, but it works so well that I can't live without it anymore. The logs are then inserted into a wide DB table with all the field one could ever want to examine thanks to the variadic parameter.
  • hu3 10mo ago
    Nice. I guess you write logs on the "final" block of a global try/catch/final? Something like: try { // handle request code } catch (...) { // add exceptions to log } final { // insert logs into DB }
    • wesammikhail 10mo ago
      I used to do it like that and it worked really well but I changed the flow to where exceptions are actually part of the control flow of the app using PHP's set_exception_handler(), set_error_handler() and register_shutdown_function(). Example, lets say a user forgot to provide a password when authenticating, then I will throw a ClientSideException(400, "need password yada yada"); That exception will bubble up to the exception_handler that logs and outputs the proper message to the screen. Similarly if ANY exception is thrown, regardless of where it originated, the same will happen. When you embrace exceptions as control flow rather than try to avoid them, suddenly everything gets 10x easier and I end up writing much less code overall.
      • hu3 10mo ago
        I love Exceptions as control flow! Thanks for the suggestion. I too use specialized exceptions. Some have friendly messages that can be displayed to the user, like "Please fill the password". But critical exceptions display a generic error to the user ("Ops, sorry something went wrong on our side...") but log specifics to devs, like database connection errors, for example.
• pastage 10mo ago
  Having logs in the format "connection X:Y accepted at Z ns for http request XXX" and then a "connection X:Y closed at Z ns for http response XXX" is rather nice when debugging issues on slow systems.
• hansvm 10mo ago
  If that's an issue (visibility into middle layers) it just means your events aren't wide enough. There's no fundamental difference between log.error(data) and wide_event.attach(error, data), nor similar schemes using parameters rather that context/global-based state. There are still use cases for one or the other strategy, but I'm not a fan of this explanation in either direction.
  • yallpendantools 10mo ago
    > If that's an issue (visibility into middle layers) it just means your events aren't wide enough. I hate this kind of No-True-Scotsman handwaves for how a certain approach is supposed to solve my problems. "If brute-force search is not solving all your problems, it just means your EC2 servers are not beefy enough." I gotta admit, I don't quite "get" TFA's point and the one issue that jumped out at me while reading it and your comment is that sooner than later your wide events just become fat, supposedly-still-human-readable JSON dumps. I think a machine-parseable log-line format is still better than wide events, each line hopefully correlated with a request id though in practice I find that user id + time correlation isn't that bad either. >> [TFA] Wide Event: A single, context-rich log event emitted per request per service. Instead of 13 log lines for one request, you emit 1 line with 50+ fields containing everything you might need to debug. I am not convinced this is supposed to help the poor soul who has to debug an incident at 2AM. Take for example a function that has to watch out for a special kind of user (`isUserFoo`) where "special kind" is defined as a metric on five user attributes. I.e., lambda isUserFoo(u): u.isA && (u.isB || u.isC) && (u.isD || u.isE) With usual logging I might find <timestamp> : <function> : {"level": "INFO", "requestID": "xxxaaa", "msg": "user is foo"} Which immediately tells me that foo-ness is something I might want to pay attention to in this context. With wide events, as I understand it, either you log the user in the wide event dump with attributes A to E (and potentially more!) or coalesce these into a boolean field `isUserFoo`. None of which tells me that foo-ness might be something that might be relevant in this context. Multiply that with all the possible special-cases any logging unit might have to deal with. There's bar-ness which is also dependent on attributes A-E but with different logical connectives. There's baz-ness which is `isUserFoo(u) XOR (217828 < u.zCount < 3141592)`. The wide event is soooo context-rich I'm drowning.
• cpill 10mo ago
  I wonder if one might solve this by using an accumulator that merges objects as they are emitted based on some ID (i.e. request ID say) and then ether emits the object on normal execution or a global exception handler emits it on error...?
  • runeks 10mo ago
    I was going to say that. That definitely would be a solution (and ought to be the way it works).