How would I typically log an exception?
I thought of one line per exception in the chain plus a full
trace for the last exception in the chain.

So the messages would be like:
  Initialization failed.
  Could not load configuration.
  File "~/.config/app/settings.ini" no found.
  Stack trace (outer to inner):
    _Dmain_yadda_yadda+120
    Config.__ctor(…)+312
    …
    File.__ctor(…)+12

So far so good, but I'm stuck at this line of code (where `e`
is a Throwable):

  error(e.msg, e.line, e.file, funcName, prettyFuncName, moduleName);

I don't know how to get at the function and module name where the exception was thrown. I know this stuff is part of the symbolic debug information, but I would think it is a common use case of a logger to log exceptions.

Is it? And if so, what do we want to do about it?

-- 
Marco

Am 01.10.2014 14:49, schrieb Robert burner Schadek:
> On Wednesday, 1 October 2014 at 10:50:54 UTC, Kevin Lamonte wrote:
>> I haven't tested it yet, but have two questions anyway:
>>
>> 1. I did not see any reference to the use of Clock.currTime(), which
>> on the last round accounted for about 90% of the total time spent in a
>> log call.  Reference: https://issues.dlang.org/show_bug.cgi?id=13433
>> .  (This is the difference between logging-and-filtering ~100k
>> logs/sec and ~1M logs/sec for loggers that use criteria other than
>> logLevel for filtering messages.)  Same question for this cycle:  Does
>> std.logger API need a method for clients or subclasses to
>> change/defer/omit the call to Clock.currTime?  Or defer for a change
>> in std.datetime?
>>
>
> maybe I should add a disableGetSysTime switch

Don't know if this is still the case, but calling Clock.currTime() used to allocate on each call, whereas Clock.currTime(UTC()) didn't and thus was orders of magnitudes faster.

Am 01.10.2014 17:05, schrieb Robert burner Schadek:
> On Wednesday, 1 October 2014 at 14:24:52 UTC, Marco Leise wrote:
>> Am Wed, 01 Oct 2014 12:49:29 +0000
>> schrieb "Robert burner Schadek" <rburners@gmail.com>:
>>
>> If you disable time completely, what would the LogEntry
>> contain as the time stamp? SysTime.init?
>
> That was my first idea.

It should be noted that SysTime.init.toString() currently crashes (at least some other methods, too).

I still think that there should be the two predefined log levels "debug" (for developer related diagnostics) and "diagnostic" (for end user related diagnostics) between "trace" and "info". This is important for interoperability of different libraries, so that they have predictable debug output.

But independent of that, there should really be a function for safely generating the user defined intermediate log levels, maybe like this:

    LogLevel raiseLevel(LogLevel base_level, ubyte increment)
    {
        assert(base_level is a valid base level);
        assert(base_level + increment smaller than the next base level);
        return cast(LogLevel)(base_level + increment);
    }

    // ok
    enum notice = raiseLevel(LogLevel.info, 16);

    // error, overlaps with the next base level
    enum suspicious = raiseLevel(LogLevel.info, 32);

Casting to an enum type is a pretty blunt operation, so it should at least be made as safe as possible.

On Thursday, 2 October 2014 at 18:11:26 UTC, Marco Leise wrote:
> How would I typically log an exception?

We could add a Throwable reference in LogEntry and some overrides.  But how exception stack traces appear in the output (multiple lines, all-on-one line, e.msg only, following the chain, etc.) should not be firmly set here:  we can provide a reasonable baseline in FileLogger, but other Logger subclasses will definitely want to do different things.

Another issue is that in practice one will often want to log at debug an exception they are about to throw (libraries), but log at error anything they actually catch (applications).  Should we include those use cases too?  This skirts very close to the "policy, not mechanism" line, but might be worth it.

Proposal:

   LogEntry {
       ...
       Throwable throwable; /// Optional Throwable
       bool caught;         /// If true, then throwable was logged via caught/caughtf
   }

   void throwing(Throwable t, string msg) {...}
   void throwingf(Throwable t, string formatMsg, A... args) {...}
   void caught(Throwable t, string msg) {...}
   void caughtf(Throwable t, string formatMsg, A... args) {...}

Thoughts?

On Thursday, 2 October 2014 at 18:11:26 UTC, Marco Leise wrote:
> How would I typically log an exception?
> I thought of one line per exception in the chain plus a full
> trace for the last exception in the chain.
>
> So the messages would be like:
>   Initialization failed.
>   Could not load configuration.
>   File "~/.config/app/settings.ini" no found.
>   Stack trace (outer to inner):
>     _Dmain_yadda_yadda+120
>     Config.__ctor(…)+312
>     …
>     File.__ctor(…)+12
>
> So far so good, but I'm stuck at this line of code (where `e`
> is a Throwable):
>
>   error(e.msg, e.line, e.file, funcName, prettyFuncName, moduleName);
>
> I don't know how to get at the function and module name where
> the exception was thrown. I know this stuff is part of the
> symbolic debug information, but I would think it is a common
> use case of a logger to log exceptions.

I guess that should be part of the Exception. I have no idea how to get __FUCTION__ of and Exception from inside another function.

>
> Is it? And if so, what do we want to do about it?

On Thursday, 2 October 2014 at 20:15:32 UTC, Sönke Ludwig wrote:
> I still think that there should be the two predefined log levels "debug" (for developer related diagnostics) and "diagnostic" (for end user related diagnostics) between "trace" and "info". This is important for interoperability of different libraries, so that they have predictable debug output.
>
> But independent of that, there should really be a function for safely generating the user defined intermediate log levels, maybe like this:
>
>     LogLevel raiseLevel(LogLevel base_level, ubyte increment)
>     {
>         assert(base_level is a valid base level);
>         assert(base_level + increment smaller than the next base level);
>         return cast(LogLevel)(base_level + increment);
>     }
>
>     // ok
>     enum notice = raiseLevel(LogLevel.info, 16);
>
>     // error, overlaps with the next base level
>     enum suspicious = raiseLevel(LogLevel.info, 32);
>
> Casting to an enum type is a pretty blunt operation, so it should at least be made as safe as possible.

from log4d
/// Aliases for debugX and fineX functions
alias debug1  = defaultLogFunction!(Log4DLogger.LOG_LEVEL_DEBUG1);
alias debug2  = defaultLogFunction!(Log4DLogger.LOG_LEVEL_DEBUG2);
alias debug3  = defaultLogFunction!(Log4DLogger.LOG_LEVEL_DEBUG3);

but adding a raiseLevel function should be no problem

On Thursday, 2 October 2014 at 10:37:02 UTC, Kevin Lamonte wrote:
>
> Would PR https://github.com/D-Programming-Language/phobos/pull/1910 provide a way given a Tid to determine: a) What underlying concurrency model it is using (Thread, Fiber, process, future)? b) Uniquely identify that structure (Thread ID string, Fiber address string, process ID, something else)?  c) Be capable of using that identifying immutable (because it needs to be send()able to another Tid writing to network/file/etc) string-representable thing to find the original Tid again?  A+B is necessary for using std.logger to debug concurrent applications, C is a very nice-to-have that comes up periodically.

register() is meant to provide a means of referring to a thread.  But the relevant thing there is finding a thread by role, not by instance.  So if a thread doing a known job terminates, a new one can spawn and register under the same name so proper operation can continue.  Having an identifier for logging is a bit different.  Would using the MessageBox address be sufficient?  I'd be happy to add a Tid.id property that returns a value like this.  I'd rather not try to generate a globally unique identifier though (that would probably mean a UUID, which is long and expensive to generate).

On Sunday, 5 October 2014 at 17:06:06 UTC, Sean Kelly wrote:

> Having an identifier for logging is a bit different.  Would using the MessageBox address be sufficient?  I'd be happy to add a Tid.id property that returns a value like this.  I'd rather not try to generate a globally unique identifier though (that would probably mean a UUID, which is long and expensive to generate).

I think Tid.id returning the MessageBox address would be fine for logging purposes.  The main value is being able to distinguish messages coming in at the same time from multiple threads.  Even if a MessageBox address was re-used by a new receive()er after a previous one exited I doubt it would confuse users very much.  I thing that a doc on Tid.id like "this value will not be the same as any other Tid currently existing, but might be the same as a Tid that has exited previously" would be sufficient.

On Sunday, 5 October 2014 at 23:40:32 UTC, Kevin Lamonte wrote:
> On Sunday, 5 October 2014 at 17:06:06 UTC, Sean Kelly wrote:
>
>> Having an identifier for logging is a bit different.  Would using the MessageBox address be sufficient?  I'd be happy to add a Tid.id property that returns a value like this.  I'd rather not try to generate a globally unique identifier though (that would probably mean a UUID, which is long and expensive to generate).
>
> I think Tid.id returning the MessageBox address would be fine for logging purposes.  The main value is being able to distinguish messages coming in at the same time from multiple threads.  Even if a MessageBox address was re-used by a new receive()er after a previous one exited I doubt it would confuse users very much.  I thing that a doc on Tid.id like "this value will not be the same as any other Tid currently existing, but might be the same as a Tid that has exited previously" would be sufficient.

A moving GC can affect the address, too, but for your purpose it would still be fine, you just mustn't put too much significance into the actual value.