Log standard

[alexander-m-pusch]

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

[oeed]

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]

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

[alexander-m-pusch]

just edited some stuff, added a bit further information

[viluon]

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]

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

[lyqyd]

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]

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]

@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]

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]

I see

[Admicos]

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!