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

Log standard #62

Open
wants to merge 13 commits into
base: master
Choose a base branch
from
Open

Log standard #62

wants to merge 13 commits into from

Conversation

alexander-m-pusch
Copy link

I thought a log standard for debugging and diagnostics would be useful, couls be used as a way to store data.

@oeed
Copy link
Owner

oeed commented Nov 2, 2016

I can see the benefits of having this format specified. However I think you need to define the format a bit more and fix the formatting a bit. For example, how the time string is specified, how messages are delimited (new lines).

@oeed
Copy link
Owner

oeed commented Nov 3, 2016

@lyqyd @SquidDev @viluon @apemanzilla any thoughts? Do we need this?

@alexander-m-pusch
Copy link
Author

just edited some stuff, added a bit further information

@viluon
Copy link
Collaborator

viluon commented Nov 3, 2016

A log file standard would definitely be useful. However, there are a few issues I can see with your proposal @MrObsidy.

First off, keeping the time in a 24-hour format is a really strange idea, and I would even say it's not viable or useful for log files at all. I have never seen a log file use that. Instead (and I think this makes much more sense), the time strings are commonly expressed as time since the application started. This allows for easy debugging and anyone reading the log output can directly examine how long did each action take.

Secondly, having one type of informative messages and 3 levels of errors is particularly strange, too. Usually people use "info", "warn", and "error". It's a much clearer system, and one shorter to read and write, too. Note that it is not needed to separate errors that will crash the program and errors that can be recovered from, since in most cases the former group of problems will also end the log file. Some freedom in specifying custom log entry types would be cool though, perhaps the log file could start with a listing of enabled format extensions?

Another issue that I can see here is that you don't use any indenting in the log entry prefix. Different times will have different length (as the number of seconds passed since start up increases, obviously). It is much easier to read a log that is indented so that all (or at least most) log entries start at the same column. Usually this is achieved either by using tabs, or by having the log function count the prefix text length and appending/prepending spaces as necessary.

Lastly, semantic versioning uses exactly 3 numeric values, MAJOR, MINOR, and PATCH. You use 4 (1.0.0.0).

These are the issues I noticed at a first glance on your proposal. I'll try to keep up to date with your changes.

And now, idea time!

On a number of occasions, one needs to log that multiple operations are going on simultaneously or in the background. The linux kernel, for example, uses an animation of sorts to notify the user that "A start job is running for X". When there are multiple start jobs, it loops through them on the screen, in that single line.

Logs should have at least a limited support for colours. Providing an API that would print them to the screen with proper highlighting would be awesome! It wouldn't have to be much, I was thinking blue for "info", yellow for "warn" and red for "error". I suggest only the label to actually be highlighted. Adding some support for ansicolors in the log entry content would also help.

You may want to take some inspiration from the linux kernel's style of logs. It merges a verbose notation of the current date and time with better-than-millisecond precise time since start up. While booting, it only actually displays the part after the verbose notation. Note how it doesn't use a colon after the ending square bracket, instead it uses one to specify which job or function is responsible for the log entry, which is a very cool feature.
Here's an excerpt:

Nov  2 20:01:20 deluon kernel: [    4.259863] [drm] Initialized drm 1.1.0 20060810
Nov  2 20:01:20 deluon kernel: [    4.653372] nvidia: module license 'NVIDIA' taints kernel.
Nov  2 20:01:20 deluon kernel: [    4.653376] Disabling lock debugging due to kernel taint
Nov  2 20:01:20 deluon kernel: [    4.661927] vgaarb: device changed decodes: PCI:0000:01:00.0,olddecodes=io+mem,decodes=none:owns=none
Nov  2 20:01:20 deluon kernel: [    4.662148] [drm] Initialized nvidia-drm 0.0.0 20150116 for 0000:01:00.0 on minor 0
Nov  2 20:01:20 deluon kernel: [    4.662155] NVRM: loading NVIDIA UNIX x86_64 Kernel Module  352.79  Wed Jan 13 16:17:53 PST 2016
Nov  2 20:01:20 deluon kernel: [    5.292633] EXT4-fs (sda5): re-mounted. Opts: errors=remount-ro
Nov  2 20:01:20 deluon kernel: [    5.673615] ACPI: acpi_idle registered with cpuidle
Nov  2 20:01:20 deluon kernel: [    5.702968] acpi-cpufreq: overriding BIOS provided _PSD data
Nov  2 20:01:20 deluon kernel: [    5.764717] input: Power Button as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0C:00/input/input3
Nov  2 20:01:20 deluon kernel: [    5.764726] ACPI: Power Button [PWRB]
Nov  2 20:01:20 deluon kernel: [    5.764843] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input4
Nov  2 20:01:20 deluon kernel: [    5.764849] ACPI: Power Button [PWRF]
Nov  2 20:01:20 deluon kernel: [    5.844532] wmi: Mapper loaded
Nov  2 20:01:20 deluon kernel: [    5.926531] EDAC MC: Ver: 3.0.0

Thanks a lot for contributing to CraftOS-Standards!! Best luck to you @MrObsidy.

@alexander-m-pusch
Copy link
Author

Tl;dr right now (12:32PM here in Vancouver). I am gonna read this tomorrow, seems good though. Good night!

@lyqyd
Copy link
Collaborator

lyqyd commented Nov 3, 2016

The version number also needs to be present in the information table at the top. I think that the levels should be DEBUG, INFO, WARN, ERROR. A log viewer program could then filter the logs to only show messages at or above a chosen level.

I think that log entries should be composed of four elements: timestamp, level, source, message. This enables program-specific logging as well as system-wide logging, where logged messages may come from many sources, as in @viluon's example above.

@alexander-m-pusch
Copy link
Author

i read it, I see your point, could take some time to fix it though. (High school is being a b*tch right now, sorry)

@alexander-m-pusch
Copy link
Author

@lyqyd what I thought of is every program creating its own log, making a "source" tag somewhat pointless (although it could be used to determine the currently/last operating function)

Finally at the pc now.

@oeed
Copy link
Owner

oeed commented Nov 3, 2016

every program creating its own log, making a "source" tag somewhat pointless

By having a source tag though it allows you to have system wide logging. These formats should try to accommodate as many situations as possible so they actually get used.

@alexander-m-pusch
Copy link
Author

I see

@Admicos
Copy link

Admicos commented Nov 4, 2016

So, i saw that there was no available utilities for this standard, so i just made this in a hour or so. Currently it isn't following the standard, but once the standard gets finalized and included in the repo, i'll be sure to update to match the standard.

Here is what the "test.lua" file creates:

File: /var/log/testing.log

[    22.913][INFO ]: info!
[    22.917][WARN ]: warning!
[    22.921][ERROR]: error!

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

Successfully merging this pull request may close these issues.

5 participants