Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

v0.12.0 Misc enhancements #88

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
Open

v0.12.0 Misc enhancements #88

wants to merge 1 commit into from

Conversation

zah
Copy link
Contributor

@zah zah commented Sep 30, 2020

  • Log levels can be specified per sink

  • When a log statements logs an exception, the stack trace of the
    exception will be printed in a more readable form (on multople
    indented lines with one call stack entry per line).
    The feature is enabled only in debug builds or when explicitly
    requested with -d:chronicles_stack_traces:on.

  • The printing of complex objects in the formats textlines and textblocks
    has been improved. Type-specific overrides such as chronicles.formatIt
    will now affect the formatting of the object fields.

  • Most log statements won't perform any allocations.
    The details depend on the logged object types.

  • The type of line ending characters used by Chronicles can be
    controlled with -d:chronicles_line_endings. Supported values
    are 'windows', 'posix` and 'platform'.

@arnetheduck
Copy link
Member

When a log statements logs an exception, the stack trace of the will be printed in a more readable form (on multople lines with one call stack entry per line).

this breaks grep/sed and standard log ingesters for central log analysis tools with testlines which is a primary reason to use textlines to begin with - better would be to format them with a semi-readable single line format, maybe separating each part with / - with spaces, which are currently missing and makes them hard to read on a terminal

@zah
Copy link
Contributor Author

zah commented Sep 30, 2020

I did research this problem during the initial design phase of Chronicles and found many tools that can support such stack traces. The use of multi-line stack traces is quite prevalent in Java and the Java world is extremely reliant on logging, which puts pressure on all logging tools to support them.

It's true that a custom configuration is often required, but it's usually quite easy to define one. Here are some examples:

https://logz.io/blog/shipping-multiline-logs-with-filebeat/
https://coralogix.com/log-analytics-blog/parsing-multiline-logs-the-complete-guide/

Even with this argument aside, let's not forget that Chronicles recommends Json logging for data ingestion and the text formats for on-screen logging. That's also the configuration that we are going to use in NBC and I think there is value in optimizing the readability of the on screen text for developers and users.

@arnetheduck
Copy link
Member

arnetheduck commented Sep 30, 2020

readability of the on screen text for developers and users.

indeed, and when debugging and reading logs I'm working with a suite of tools that are all adapted to single line, and these tools work together with little friction between them - that's the whole point of the textlines format, so that one event equals one line - so that line breaking is done by my terminal or my text editor at the word wrap extent and not elsewhere etc - indeed, that's why I'm suggesting to ensure that when a line break would be expected in a multi-line format like text blocks, a word-wrap friendly separator be used.

just like log parsers (which right now can be looped over with for line in open(xxx) in python), all tools out there can be made to work with multiline formats - sed, awk, bash, python, nim readline, etc etc - it's just harder and slows down using the log output in a productive way (above all because I have to break my flow and go look for how to do the exceptional multiline configuration for the tool)

@zah
Copy link
Contributor Author

zah commented Sep 30, 2020

I'll be happy to add an experimental configuration option for this that would allow us to see what's more useful in practice.
I suspect you are not grepping the stdout of the beacon node? Do you disable the colors and the status bar in order to do so? It's also questionable if seeing stack traces in the grep output is useful - perhaps you'll appreciate the less noisy results.

@arnetheduck
Copy link
Member

well, I'm not going to learn a special option for it - I want fewer options, not more - I want textlines, a explicit single-line format, to... er... stay in a single line, because that's what all my other tools are used to.

I'm just going to be mildly annoyed every time I have to hunt down stack trace after having used grep etc (now I can grep for an oid and get all information pertaining to a certain connection - with this option, I'll have to do a second search by... what.. timestamp maybe to find the stack trace) - and yes, I do use grep with the format because it's easier to redirect stdout than learning complicated output options - keep in mind that chronicles is a minority library and only one in a plethora of other libraries and applications that I encounter - I don't want to keep in mind yet another useless option.

when redirecting, the bar is not there anyway, and the colors don't bother or help me. I don't need the line to be less noisy - my wordwrapping editor and terminal achieve the same effect, but better, because they use the full width of my screen. I don't want multiple lines.

@arnetheduck
Copy link
Member

fwiw, this is the way users work, generally - options are a pita except the frivolous ones (advanced options require too much background knowledge to properly judge - it's your job as an expert to make these choices) - status-im/nimbus-eth2#1647 is a good example - stdout, redirected - not the fancy json output - because that's where the path of least resistance leads, when combining with other tooling.

if you absolutely must break the single-line format, don't bother adding options to unbreak it - it's too complicated to use them anyway and they would just make the implementation more buggy.

@zah
Copy link
Contributor Author

zah commented Oct 1, 2020

Here is my proposal - I'll add the option, but I'll make your preference the default choice to make your life easier. I'll use both settings for an extended period of time (e.g. weeks) and I'll decide on the default before Chronicles 1.0 is released.

There are two groups of people to consider here - end users of the software who can recognize polished software when they see it and developers who need all the help they can get while debugging issues. I think it's rather unquestionable that the properly formatted stack traces will be considered superior by the end users if they accidentally see them on their screens. This should have been the rationale for all the Java logging libraries that decided to log stack traces on multiple lines (if only they knew better, right?).

Now, the developers spend all their time with the software and they can invest time to improve their environment to get more productive. Everyone is used to different tools and workflows, so it's harder to come up with a "one size fits all" solution. I, for example, tend to consume the logs in Vim where I mostly use the search features, but occasionally use a grep-like folding feature where Vim hides all non-matching lines, but you can easily "unfold" the surroundings of any line. In this environment, the multi-line formatting may be beneficial because Vim has some unpleasant side effects of overly long lines (reduced responsiveness, more difficulty in positioning your cursor exactly where you want, etc).

There is a simple transformation from indented blocks to lines - just replace every occurrence of "\n " (space after new line) with " ". A developer can easily create a shell alias for this and start using it where appropriate. If the pain from multiple lines were stronger, the Java people would have convinced every grep tool to support the outline grep mode as an option. Maybe this would happen one day if libraries like Chronicles add to the pain :)

import
stew/objects

let timezone = toArray(6, now().format("zzz"))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this needs to be updated regularly (when (time mod 15 minutes) changes afair, some countries are off by 15/45 minutes, but I don't remember if there are other odditites) or you'll miss DST which change the UTC offsets as well as regulatory changes which change the timezone definitions

formatFloat(epochTime(), ffDecimal, 6)

template timestamp(record): string =
when record.timestamps == RfcTime:
template writeTs*(record) =
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the way to implement this efficiently is to cache the timezone offset (in seconds), then offset the incoming time accordingly, and print the offset time as if it were utc and finally making sure the offset is printed as well - this makes it correct, efficient and generic to all time formats

@zah zah force-pushed the log-formats branch 4 times, most recently from bda4246 to 89c3109 Compare November 4, 2021 11:06
* Log levels can be specified per sink.

* The log format can now be specified at run-time.

* The usage of colors can be controlled at run-time (fixes #1).

* Use UTC timestamps by default.

* Added a new 'LocalRfcTime' timestamp scheme to preserve the old
  behavior of logging local time.

* When a log statements logs an exception, the stack trace of the
  exception will be printed in a more readable form (on multiple
  indented lines with one call stack entry per line).

  The feature is enabled only in debug builds or when explicitly
  requested with `-d:chronicles_stack_traces:on`.

* The printing of complex objects in formats `textlines` and `textblocks`
  has been improved. Type-specific overrides such as `chronicles.formatIt`
  will now affect the formatting of the object fields.

* Most log statements won't perform any allocations.
  The details depend on the logged object types.

* The type of line ending characters used by Chronicles can be
  controlled with `-d:chronicles_line_endings`. Supported values
  are 'windows', 'posix` and 'platform'.

* Some unprintable characters are now displayed as hex value

* Rename the automatically inserted 'file' property to 'src' in
  order to avoid clashes with user variables (i.e. 'file' is a
  common variable name).

* The 'dynamic' sinks are now renamed to 'callback' to free the
  'dynamic' term for other uses.

* Updated the list of TODO items
@arnetheduck
Copy link
Member

is this still relevant?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants