www.digitalmars.com         C & C++   DMDScript  

digitalmars.D - LogLevel [was std.experimental.logger formal review round 3]

reply Martin Nowak <code+news.digitalmars dawg.eu> writes:
I just found a very compelling alternative solution to the LogLevel 
disabling problem. This was one of the reasons for the delay of std.log 
and the current solution still isn't great [1].

This idea here achieves
- fine grained control over log levels (per module/package)
- zero overhead for statically disabled log levels
- zero (almost) boilerplate (works even with the global stdlog)
- and it establishes a nice convention to enable logging for a library
   `pkg.logLevel = LogLevel.info;`

Basically it works by declaring a logLevel in a module or package.
Then the std.logger module does a reverse lookup of that declaration.

```d
module mymod;

import std.logger;

// can be anything that converts to a LogLevel
// calls with lower log level can be optimized away if this is a compile 
time constant
// runtime values also work nicely but incur a small overhead
// if this declaration is not present, logLevel from the package is used 
or the default LogLevel.

enum logLevel = LogLevel.critical;

void foo()
{
     info("information from foo"); // optimized out
     fatal("error");               // logs
}
```

https://gist.github.com/MartinNowak/443f11aa017d14007c35

There is a tiny gotcha, this works because the logger module imports the 
calling module. So we'd need to avoid module constructors in the logger 
module or use a workaround [2].

Also it can lead to additional imports when the whole package is 
imported to resolve logLevel.  This can be avoided though by declaring 
logLevel in a separate module and making it available in every module of 
a package.

```d
module mypkg.loglevel;

LogLevel logLevel;
```
```d
module mypkg.foo.bar;

public import mypkg.logLevel;

void baz(T)(T t)
{
     info("baz");
}
```

[1]: http://forum.dlang.org/post/m2p3r6$148j$1 digitalmars.com
[2]: 
https://github.com/D-Programming-Language/phobos/blob/9a46840c2b36beb6711244ec4340c117fc91a0f1/std/stdiobase.d
Dec 03 2014
next sibling parent reply Rikki Cattermole <alphaglosined gmail.com> writes:
On 4/12/2014 2:10 p.m., Martin Nowak wrote:

 I just found a very compelling alternative solution to the LogLevel
 disabling problem. This was one of the reasons for the delay of std.log
 and the current solution still isn't great [1].

 This idea here achieves
 - fine grained control over log levels (per module/package)
 - zero overhead for statically disabled log levels
 - zero (almost) boilerplate (works even with the global stdlog)
 - and it establishes a nice convention to enable logging for a library
    `pkg.logLevel = LogLevel.info;`

 Basically it works by declaring a logLevel in a module or package.
 Then the std.logger module does a reverse lookup of that declaration.

 ```d
 module mymod;

 import std.logger;

 // can be anything that converts to a LogLevel
 // calls with lower log level can be optimized away if this is a compile
 time constant
 // runtime values also work nicely but incur a small overhead
 // if this declaration is not present, logLevel from the package is used
 or the default LogLevel.

 enum logLevel = LogLevel.critical;

 void foo()
 {
      info("information from foo"); // optimized out
      fatal("error");               // logs
 }
 ```

 https://gist.github.com/MartinNowak/443f11aa017d14007c35

 There is a tiny gotcha, this works because the logger module imports the
 calling module. So we'd need to avoid module constructors in the logger
 module or use a workaround [2].

 Also it can lead to additional imports when the whole package is
 imported to resolve logLevel.  This can be avoided though by declaring
 logLevel in a separate module and making it available in every module of
 a package.

 ```d
 module mypkg.loglevel;

 LogLevel logLevel;
 ```
 ```d
 module mypkg.foo.bar;

 public import mypkg.logLevel;

 void baz(T)(T t)
 {
      info("baz");
 }
 ```

 [1]: http://forum.dlang.org/post/m2p3r6$148j$1 digitalmars.com
 [2]:
 https://github.com/D-Programming-Language/phobos/blob/9a46840c2b36beb6711244ec4340c117fc91a0f1/std/stdiobase.d


I also just wrote some test code based upon this idea.

$ cat a.d
module a;

enum level = "test";

void main() {
         test("hi");
}

void test(T, string module_ = __MODULE__)(T t) {
         import std.stdio;
         mixin("static import mod = " ~ module_ ~ ";");
         writeln(mod.level, ": ", t);
}

$ cat b.d
module b;
import a;

enum level = "BModule";

void afunc() {
         test("something");
}

static this() {
         import std.stdio;
         writeln("static this on b");
}


shared static this() {
         import std.stdio;
         writeln("shared static this on b");
}

$ rdmd b.d
shared static this on b
static this on b
test: hi

Okay its a lot simpler and far less context specific.
One thing I think should be addressed is at runtime, to override these 
defaults.
At both function/method level and at module level.

I'm not sure much can be done about module constructors, but static 
imports would probably be the best place to begin.
Now theoretically it should also be a good place to look at using UDAS 
to override per function/method. Same goes for with statements for 
runtime changes.

But in any case this is suddenly going into terms of frameworks not just 
logging libraries and making me go *shudder* not for phobos.
Dec 03 2014
parent Martin Nowak <code+news.digitalmars dawg.eu> writes:
On 12/04/2014 03:41 AM, Rikki Cattermole wrote:

 Okay its a lot simpler and far less context specific.
 One thing I think should be addressed is at runtime, to override these
 defaults.


Just use a value instead of an enum, and you can configure the log level 
at runtime.
https://gist.github.com/MartinNowak/443f11aa017d14007c35#file-main-d
Dec 03 2014
prev sibling next sibling parent "Vic" <vic.cvc gmx.com> writes:
(I don't want to hijack the thread, and I'm so happy for donated 
hours. If I my just touch on that JRE size maintenance team did 
not add logging till 1.4
http://www.onjava.com/pub/a/onjava/2002/03/06/topten.html
- instead people used downstream. Pardon me)
Dec 03 2014
prev sibling next sibling parent reply Jacob Carlborg <doob me.com> writes:
On 2014-12-04 02:10, Martin Nowak wrote:

 I just found a very compelling alternative solution to the LogLevel
 disabling problem. This was one of the reasons for the delay of std.log
 and the current solution still isn't great [1].

 This idea here achieves
 - fine grained control over log levels (per module/package)
 - zero overhead for statically disabled log levels
 - zero (almost) boilerplate (works even with the global stdlog)
 - and it establishes a nice convention to enable logging for a library
    `pkg.logLevel = LogLevel.info;`

 Basically it works by declaring a logLevel in a module or package.
 Then the std.logger module does a reverse lookup of that declaration.


This is kind of cool that you can do in D, but it feels like a hack. I 
have stopped following the std.log thread, could you summarize what 
issues you're having and trying to solve and why not a more obvious 
solution doesn't work?

-- 
/Jacob Carlborg
Dec 04 2014
parent reply "Martin Nowak" <code dawg.eu> writes:
On Thursday, 4 December 2014 at 08:14:56 UTC, Jacob Carlborg 
wrote:

 On 2014-12-04 02:10, Martin Nowak wrote:

 I just found a very compelling alternative solution to the 
 LogLevel
 disabling problem. This was one of the reasons for the delay 
 of std.log
 and the current solution still isn't great [1].

 This idea here achieves
 - fine grained control over log levels (per module/package)
 - zero overhead for statically disabled log levels
 - zero (almost) boilerplate (works even with the global stdlog)
 - and it establishes a nice convention to enable logging for a 
 library
   `pkg.logLevel = LogLevel.info;`


 This is kind of cool that you can do in D, but it feels like a 
 hack. I have stopped following the std.log thread, could you 
 summarize what issues you're having and trying to solve and why 
 not a more obvious solution doesn't work?


Zero overhead for statically disabled log levels.
The current proposal uses global version identifiers to alter the 
behavior of std.logger.
Fine grained (at least per library) control over log levels.
The current proposal required to use different logger wrappers in 
each library and scoped global version identifiers, see [1] in 
the OP.
Dec 04 2014
next sibling parent reply "Ola Fosheim =?UTF-8?B?R3LDuHN0YWQi?= writes:
On Thursday, 4 December 2014 at 10:16:52 UTC, Martin Nowak wrote:

 On Thursday, 4 December 2014 at 08:14:56 UTC, Jacob Carlborg

 hack. I have stopped following the std.log thread, could you 
 summarize what issues you're having and trying to solve and 
 why not a more obvious solution doesn't work?


 Zero overhead for statically disabled log levels.
 The current proposal uses global version identifiers to alter 
 the behavior of std.logger.
 Fine grained (at least per library) control over log levels.
 The current proposal required to use different logger wrappers 
 in each library and scoped global version identifiers, see [1] 
 in the OP.


I like the direction you are taking, but I think the better 
solution is to have:

1. A manifest/config file where you configure these and other 
settings in a uniform manner.

2. Provide support for configurations and switching between 
configurations at realtime.

3. Compiler support for the manifest file that allows library 
code to query it at compile time as well as generating bitfields 
for real time switching between configurations. (Just memcpy to 
change configuration)

4. Have logInfo(…) etc as always inlined stubs.

5. Have one bit per log level (32 should be sufficient), rather 
than a number.

6. Allow for compiler profiling so that bits in the configuration 
that are accessed together become co-located on the same word/64 
bytes cacheline.

Something like this:

<configuration name="normal">
   <module match="*">
     <logging type="info" status="off"/>
     <logging type="error" status="on" logger="file" 
href="file://var/myfile.txt"/>
   </module>
    <module match="http">
     <logging type="info" status="on" logger="remote"/>
    </module>
</configuration>

<configuration name="debug" inherit="normal">
   <module match="mylib.*[has_symbol('DEBUG')]">
     <logging type="debug" status="on" />
   </module>
</configuration>
Dec 04 2014
next sibling parent reply "Robert burner Schadek" <rburners gmail.com> writes:
As I have explained countless times, the configuration in source 
and through inheritance will always be more powerful and flexible 
than a config file. I'm not gone create any config file support, 
as there will be always one feature missing and there is just no 
way to anticipate all possible configuration requirements. So one 
shouldn't even try.
Dec 04 2014
parent reply "Ola Fosheim =?UTF-8?B?R3LDuHN0YWQi?= writes:
On Thursday, 4 December 2014 at 10:56:29 UTC, Robert burner 
Schadek wrote:

 As I have explained countless times, the configuration in 
 source and through inheritance will always be more powerful and


There is no contradiction. Configuration is level 1, 
implementation is level 2.
Dec 04 2014
parent "Robert burner Schadek" <rburners gmail.com> writes:
On Thursday, 4 December 2014 at 11:02:23 UTC, Ola Fosheim Grøstad 
wrote:

 On Thursday, 4 December 2014 at 10:56:29 UTC, Robert burner 
 Schadek wrote:

 As I have explained countless times, the configuration in 
 source and through inheritance will always be more powerful and


 There is no contradiction. Configuration is level 1, 
 implementation is level 2.


Either I don't see your point or you didn't see mine.
Dec 04 2014
prev sibling parent reply "Martin Nowak" <code dawg.eu> writes:
On Thursday, 4 December 2014 at 10:44:22 UTC, Ola Fosheim Grøstad 
wrote:

 I like the direction you are taking, but I think the better 
 solution is to have:


It's a nice idea for generic feature testing flags, but it's a 
lot of implementation work in the compiler. And it seems odd to 
implement a big part of a library in the compiler.
Dec 04 2014
parent reply "Ola Fosheim =?UTF-8?B?R3LDuHN0YWQi?= writes:
On Thursday, 4 December 2014 at 11:02:39 UTC, Martin Nowak wrote:

 It's a nice idea for generic feature testing flags, but it's a 
 lot of implementation work in the compiler. And it seems odd to 
 implement a big part of a library in the compiler.


I think D lacks a generic project configuration mechanism. I 
generally want configurations to be located in one or at least a 
few files that are easy to modify and which can have tools 
written for them. So yes, this should not be written for logger 
alone.

I don't know how much work it is for the compiler, but I suspect 
a lot of it could be written as a compiler extension in D that 
communicates with the C++ compiler core.

It would be very useful for server programmers to be able to swap 
configuration for the whole program on a live server when you 
detect a problem. Third parties could create a GUI tool for 
managing configuration settings with automatic transfer of new 
bitpatterns over tcp/udp, or even automatic rebuilds.
Dec 04 2014
parent reply "Robert burner Schadek" <rburners gmail.com> writes:
On Thursday, 4 December 2014 at 11:49:53 UTC, Ola Fosheim Grøstad 
wrote:

 I think D lacks a generic project configuration mechanism. I 
 generally want configurations to be located in one or at least 
 a few files that are easy to modify and which can have tools 
 written for them. So yes, this should not be written for logger 
 alone.


I think D lacks a good std.serialization module
Dec 04 2014
parent "Ola Fosheim =?UTF-8?B?R3LDuHN0YWQi?= writes:
On Thursday, 4 December 2014 at 12:16:54 UTC, Robert burner 
Schadek wrote:

 I think D lacks a good std.serialization module


That would be a good point if you did binary logging…
Dec 04 2014
prev sibling parent Andrei Alexandrescu <SeeWebsiteForEmail erdani.org> writes:
On 12/4/14 8:16 PM, Martin Nowak wrote:

 On Thursday, 4 December 2014 at 08:14:56 UTC, Jacob Carlborg wrote:

 On 2014-12-04 02:10, Martin Nowak wrote:

 I just found a very compelling alternative solution to the LogLevel
 disabling problem. This was one of the reasons for the delay of std.log
 and the current solution still isn't great [1].

 This idea here achieves
 - fine grained control over log levels (per module/package)
 - zero overhead for statically disabled log levels
 - zero (almost) boilerplate (works even with the global stdlog)
 - and it establishes a nice convention to enable logging for a library
   `pkg.logLevel = LogLevel.info;`


 This is kind of cool that you can do in D, but it feels like a hack. I
 have stopped following the std.log thread, could you summarize what
 issues you're having and trying to solve and why not a more obvious
 solution doesn't work?


 Zero overhead for statically disabled log levels.
 The current proposal uses global version identifiers to alter the
 behavior of std.logger.
 Fine grained (at least per library) control over log levels.
 The current proposal required to use different logger wrappers in each
 library and scoped global version identifiers, see [1] in the OP.


We should scrutinize and streamline this idiom properly. It's very 
powerful and after enshrined in Phobos it will serve everyone as a 
precedent to follow. Thanks, Martin! -- Andrei
Dec 08 2014
prev sibling next sibling parent reply "Kagamin" <spam here.lot> writes:
On Thursday, 4 December 2014 at 01:10:43 UTC, Martin Nowak wrote:

 ```d
 module mypkg.foo.bar;

 public import mypkg.logLevel;

 void baz(T)(T t)
 {
     info("baz");
 }
 ```


Not bad. Does info="baz" compile?
Dec 04 2014
parent "Martin Nowak" <code dawg.eu> writes:
On Thursday, 4 December 2014 at 08:42:36 UTC, Kagamin wrote:

 Not bad. Does info="baz" compile?


That's not my business, if it's callable with a single argument, 
it would work, but it's not  property.
Dec 04 2014
prev sibling next sibling parent reply "Robert burner Schadek" <rburners gmail.com> writes:
That is much nicer, thank you for taking the time.

Couldn't way just say that we don't import __MODULE__ but rather 
__MODULE__ ~ "_loggerinfo.d" and then describe the import 
constraint in the documentation.
Dec 04 2014
next sibling parent "Martin Nowak" <code dawg.eu> writes:
On Thursday, 4 December 2014 at 10:37:12 UTC, Robert burner 
Schadek wrote:

 That is much nicer, thank you for taking the time.

 Couldn't way just say that we don't import __MODULE__ but 
 rather __MODULE__ ~ "_loggerinfo.d" and then describe the 
 import constraint in the documentation.


Good idea, that would work for libraries (dub packages) where 
adding a single module is cheap.
It's a bit annoying for script like D usage so I'd only do this 
optionally.
But then the compiler would hit the hard disk every time you call 
log, trying to find that non-present module, so maybe it's 
simpler and more transparent to always only look in the calling 
context.
Dec 04 2014
prev sibling next sibling parent reply "Martin Nowak" <code dawg.eu> writes:
On Thursday, 4 December 2014 at 10:37:12 UTC, Robert burner 
Schadek wrote:

 That is much nicer, thank you for taking the time.

 Couldn't way just say that we don't import __MODULE__ but 
 rather __MODULE__ ~ "_loggerinfo.d" and then describe the 
 import constraint in the documentation.


Importing a different module wouldn't reliably work, when file 
paths differ from module paths.
The nice thing about importing __MODULE__ is that the compiler 
already knows it, because it's the caller.
Also importing a different file by name feels a bit too much like 
magic ruby bindings.
Dec 04 2014
parent "Robert burner Schadek" <rburners gmail.com> writes:
On Thursday, 4 December 2014 at 11:12:02 UTC, Martin Nowak wrote:

 On Thursday, 4 December 2014 at 10:37:12 UTC, Robert burner 
 Schadek wrote:

 That is much nicer, thank you for taking the time.

 Couldn't way just say that we don't import __MODULE__ but 
 rather __MODULE__ ~ "_loggerinfo.d" and then describe the 
 import constraint in the documentation.


 Importing a different module wouldn't reliably work, when file 
 paths differ from module paths.
 The nice thing about importing __MODULE__ is that the compiler 
 already knows it, because it's the caller.
 Also importing a different file by name feels a bit too much 
 like magic ruby bindings.


Well, the static if mixin stuff also a bit like magic.
How do you suggest do we solve the dependency cycle?

Anyway, the code you showed needs a default case where there is 
no LogLevel defined and no parent is left.
Dec 04 2014
prev sibling parent reply Andrei Alexandrescu <SeeWebsiteForEmail erdani.org> writes:
On 12/4/14 8:37 PM, Robert burner Schadek wrote:

 That is much nicer, thank you for taking the time.

 Couldn't way just say that we don't import __MODULE__ but rather
 __MODULE__ ~ "_loggerinfo.d" and then describe the import constraint in
 the documentation.


Perhaps that might improve error messages. I fear of things that could 
happen if a circular import via mixin fails. Andrei
Dec 08 2014
parent "Robert burner Schadek" <rburners gmail.com> writes:
On Monday, 8 December 2014 at 21:20:20 UTC, Andrei Alexandrescu 
wrote:

 On 12/4/14 8:37 PM, Robert burner Schadek wrote:

 That is much nicer, thank you for taking the time.

 Couldn't way just say that we don't import __MODULE__ but 
 rather
 __MODULE__ ~ "_loggerinfo.d" and then describe the import 
 constraint in
 the documentation.


 Perhaps that might improve error messages. I fear of things 
 that could happen if a circular import via mixin fails. Andrei


How long is a line of your terminal?

On a more serious note: I proposed "_loggerinfo.d" to counteract 
that and this file could be the place to store all logger 
configuration anybody invents. This way we would have a canonical 
place for all configuration concerning the logger.
Dec 09 2014
prev sibling parent reply "Daniel Murphy" <yebbliesnospam gmail.com> writes:
"Martin Nowak"  wrote in message news:m5ocaj$2i8t$1 digitalmars.com...


 I just found a very compelling alternative solution to the LogLevel 
 disabling problem. This was one of the reasons for the delay of std.log 
 and the current solution still isn't great [1].

 This idea here achieves
 - fine grained control over log levels (per module/package)
 - zero overhead for statically disabled log levels
 - zero (almost) boilerplate (works even with the global stdlog)
 - and it establishes a nice convention to enable logging for a library
    `pkg.logLevel = LogLevel.info;`

 Basically it works by declaring a logLevel in a module or package.
 Then the std.logger module does a reverse lookup of that declaration.


FWIW I don't really like this - it feels like a hack.  I'd rather just 
declare a private logger alias (or something like that) and use that in the 
library.  Decision can be made at compile time, doesn't require reverse 
module imports, doesn't depend on global versions.

eg

alias libraryLogger = std.logger.FilteredLogger!(LogLevel.info);
Dec 04 2014
next sibling parent Martin Nowak <code+news.digitalmars dawg.eu> writes:
On 12/04/2014 03:32 PM, Daniel Murphy wrote:

 FWIW I don't really like this - it feels like a hack.  I'd rather just
 declare a private logger alias (or something like that) and use that in
 the library.  Decision can be made at compile time, doesn't require
 reverse module imports, doesn't depend on global versions.

 eg

 alias libraryLogger = std.logger.FilteredLogger!(LogLevel.info);


That's a bit shorter but similar to what I already proposed here 
http://forum.dlang.org/post/m2k13k$12vf$1 digitalmars.com.
Something along this line would still be a good solution IMO.
Dec 04 2014
prev sibling parent reply "Dicebot" <public dicebot.lv> writes:
On Thursday, 4 December 2014 at 14:32:27 UTC, Daniel Murphy wrote:

 FWIW I don't really like this - it feels like a hack.  I'd 
 rather just declare a private logger alias (or something like 
 that) and use that in the library.  Decision can be made at 
 compile time, doesn't require reverse module imports, doesn't 
 depend on global versions.

 eg

 alias libraryLogger = std.logger.FilteredLogger!(LogLevel.info);


I agree with Daniel here. It feels like seeking for too much 
magic just because it is cool - while more simple and 
straightforward approach can do the job as well.
Dec 05 2014
parent "Robert burner Schadek" <rburners gmail.com> writes:
On Friday, 5 December 2014 at 10:30:08 UTC, Dicebot wrote:

 On Thursday, 4 December 2014 at 14:32:27 UTC, Daniel Murphy 
 wrote:

 FWIW I don't really like this - it feels like a hack.  I'd 
 rather just declare a private logger alias (or something like 
 that) and use that in the library.  Decision can be made at 
 compile time, doesn't require reverse module imports, doesn't 
 depend on global versions.

 eg

 alias libraryLogger = 
 std.logger.FilteredLogger!(LogLevel.info);


 I agree with Daniel here. It feels like seeking for too much 
 magic just because it is cool - while more simple and 
 straightforward approach can do the job as well.


Yes simpler is better, if it works. As discussed twice already, 
an approach like:
alias libraryLogger = std.logger.FilteredLogger!(LogLevel.info);
will not work.

Currently I think the best solution is Martin's idea with my mod. 
The complexity of the task to accomplish does not simple go away. 
Unless you cut features which we can't do to keep the generality 
of the library. And that is the main goal after all.
Dec 05 2014