Logging API discussion

Hi Dennis,


> On Apr 26, 2016, at 3:26 PM, Denis Kudriashov <[hidden email]> wrote:
>
> Hello.
>
> I resumed discussion about SystemLogger and Beacon here http://forum.world.st/What-the-state-of-unifying-Beacon-with-SystemLogger-td4890684.html.
> I plan to unify both approaches by saving traditional terminology from SystemLogger and cool features from Beacon.

Thanks for your effort, but as I said before, the decision was to integrate Beacon and iterate on that.


> Let's think about logging API to log any object in the system. Most natural way is just send message #log to object itself:
>
> anObject log
>
> It would be nice replacement for Object>>logCr.

This type of usage should be discouraged in my opinion. We should instead encourage people to use typed logging signals, like we should also discourage people from using
        self error: ‘a magic string here’.


> But when we log some information we usually want to log it with little remark, importance level and (most important) timestamp. This information is kind of standard for logging domain. But it requires much more methods for logging API.
> So we need extra information to put together with objects:
> • timestamp
> • user message
> • importance level (debug, info, error, etc.)

Please do not do that. This might make sense for C or Java (although it does not), but we have objects and we should filter based on those without relying on a rigid system based on random levels. Please.


> • whatever (process hash, process name for example)
> • sometimes it can be needed to put in log something different than object itself. (for example it can be just copy of object to not change state of log entry during app lifetime)
> Here is possible API based on Object extensions. It has drawbacks but it is good to think about it too:

No. This is the responsibility of the subtypes of Signal.


> "it will put anObject in logs with default #info level"
> anObject log
>
> "it will put anObject in logs with default #info level and given user message"
> anObject logWith: 'something interesting was happened with anObject’

>  "inside block we can put any logging domain information from application and also override content by specific representation"
> anObject logBy: [:logEntry |
>       logEntry message: 'something interesting to be saved with our object'
>       logEntry content: anotherObject] "here logs with interest about anObject will receive logEntry with anotherObject instead of anObject”

This will just favor more strings. We want to move away from them.



I am definitely against this.


I think this is the wrong approach and I am opposing this direction in the most constructive way I can :).

Cheers,
Doru


> Best regards,
> Denis

--
www.tudorgirba.com
www.feenk.com

"Don't give to get. Just give."

Denis,

Try to look at it this way: by using objects (events, signals, announcements, whatever) and just generating them on the spot and sending them off somewhere, you have everything you need, without imposing any restrictions.

If you want to use log/severity levels and/or categories and/or tags, you can do that. But I don't want to. Your objects will contain that info and you will be able to filter on it.

I take a very extreme standpoint here: there should be no requirements at all. Not for the kinds of objects that one can use, nor where/how they are sent to/handled.

I even do not want a specific kind of timestamp imposed. DateAndTime is way too expensive and has either too much or not enough granularity (we have no nanosecond clock). There could be some convention (a trait maybe) that says #timestamp returns a Magnitude that can be used for that purpose.

If you want a small system (builder) that makes it easier to construct and signal log events, then that could be provided, but is will always be quite specific to one person's taste.

Making log events subclasses of Announcement and using an Announcer instance local to a subsystem is one easy implementation choice, but not necessarily the only one.

One concrete (but not perfect) implementation of my ideas can be found in the package 'Zinc-HTTP-Logging' in your image.

Sven

> On 26 Apr 2016, at 17:31, Denis Kudriashov <[hidden email]> wrote:
>
>
> 2016-04-26 17:28 GMT+02:00 Denis Kudriashov <[hidden email]>:
> Please do not do that. This might make sense for C or Java (although it does not), but we have objects and we should filter based on those without relying on a rigid system based on random levels. Please.
>
> And I forgot mention that my proposed API is not prevent object filtering. All information is here. So it can be implemented. And it also can be implemented by announcements.
> But here I just want to discuss API.

Hi Denis,

I was missing this fine-grained logging also so I wrote a couple of classes, long ago, that use events. It still logs to the Transcript and to a log file, in parallel. The test doesn't even make a test, to my chagrin. Look at TraceMonitor for the output bits and at senders of Object>>#etrace: aTraceEvent for the input side. It's in the class category: OCapPresentation-Base-Trace & extensions in the Cryptography repository. I was thinking remote logging, if I can ever untangle this code. It's always a question of crafty avoidance or sitting down and digging into code. I can be crafty7.

Cheers,
Robert

Hi

2016-04-26 20:16 GMT+02:00 Sven Van Caekenberghe <[hidden email]>:

Try to look at it this way: by using objects (events, signals, announcements, whatever) and just generating them on the spot and sending them off somewhere, you have everything you need, without imposing any restrictions.

If logging system will not allow me to log arbitrary object it would be restriction. And by "log object" I mean not just adding it to some log collection. But I need ability to mark objects with tags, messages and timestamps.

 

If you want to use log/severity levels and/or categories and/or tags, you can do that. But I don't want to. Your objects will contain that info and you will be able to filter on it.

Most of objects not have timestamp, tag or user message. So I can't filter them in such naked state. And instead of generating special objects with such information I want logging library take care about it. 

Of course for some cases I will need special objects for logs. But I should not be forced to do it every time. 

-- 
Robert
.  ..   ...    ^,^

> On 26 Apr 2016, at 23:17, Denis Kudriashov <[hidden email]> wrote:
>
>
> 2016-04-26 20:16 GMT+02:00 Sven Van Caekenberghe <[hidden email]>:
> Making log events subclasses of Announcement and using an Announcer instance local to a subsystem is one easy implementation choice, but not necessarily the only one.
>
> One concrete (but not perfect) implementation of my ideas can be found in the package 'Zinc-HTTP-Logging' in your image.
>
> I look at it.

Thanks for giving feedback.

> And I saw hierarchy of ZnClientLogEvent (9 classes) which is just data objects without any behaviour.

Right now the event objects themselves are indeed pretty simple, but not totally without behaviour I would say. Most of the functionality is in the objects they encapsulate (like the request and response, the timing information).

> For each class there is method in ZnClient with #log...thisEvent pattern.  And most of this methods has only sender which executes real business logic on httpClient. For example:
>
> ZnConnectionEstablishedEvent
> ^
> logConnectionEstablishedTo: url started: initialMilliseconds
> ^
> newConnectionTo: url
>
> So for each event ZnClient has two methods.

The fact that the logging is abstracted into helper methods is not a requirement per se, it is just code organisation, preferable to super long methods. I see only one #logXXX method per log event.

> What I feel here is that if Zinc will be designed with some kind of command pattern all of this would be not needed.
> Instead of events and corresponding methods Zinc would have commands which implement real logic and can be logged directly without any special objects.
>
> I know designing http library is complex task. And maybe my idea is not applicable here.

The idea of using command objects as log objects might work in specific situations, it is a good idea, but I doubt it would be applicable to many situations, or cover all logging needs. I'll certainly think about it.

> But what I want to say: applications usually already have objects which incapsulate all needed information for logs. And logging system should not require anything else.  

But that is what is happening here (where it is applicable): the log event object that signals that a request resulted in a specific response for example, contains the actual, original objects; that is why doing this is cheap, the objects already exist.

Sven

Denis,

I'd like to mention my TraceEvent and TraceMonitor classes, again, as it supports most of what you guys are talking about. I believe I have resolved my package naming, so you can find these classes in the SqueakSource's Cryptography repository in the OCapPresents package.

TraceEvent is a single loggable event class with timestamp ivar, generic msg ivar, filterable domain ivar, remote ivar. These ivars are converted to strings during logEvent handling in the monitor, so the msg ivar can hold a user-defined loggable event objects that convert to a preferred string. There would be no need to write separate wrappers for each use.

The monitor can have various domains enabled or disabled: use TraceMonitor>>#enableDomain:/#disableDomain: with a symbol. My use has a bunch of convenience methods for my domain use, but a new domain can be added and one can use the #etrace:msg: variety, which accepts the domain as the first parameter and the domain specific msg object as the second parameter. The monitor can write to multiple trace streams.

I am missing logLevel, though I tried to add severity but it is non-functional. It would be easy enough to add. I do not know if this aligns with the Announcements solution you all are talking about or if it meets all your needs. It is sounding like it meets most of the logging domain information, it is filterable, has multiple output streams, uses the event system so it is lightly couple to the domain.

Whatever solution is arrived at, I hope it is a shared infrastructure service in squeak as well, along with Fuel, then I would likely switch to using the standard.

2016-04-27 10:43 GMT+02:00 Norbert Hartl <[hidden email]>:

I must confess I cannot follow you completely. What we were/are talking about is that the assumption a logging entry needs timestamp, log level and such is not appropriate. If you have legacy syslog style logging in mind it appears natural but for a lot of use cases it is not.

Could you provide example where it is not?

 

Even if you could say that a timestamp is part of the logging domain it is not said if that timestamp needs to be part of the log object or the logger consuming this object. This question arises for every quality of a logging object. Even the logging level could be some behavioral quality that a logger matches to log levels. Contrary to this is logging thisContext which has to be done in the log object.

I think the hard part is the way of distribution of log objects and filtering of them. While the former is being discussed with Beacon the latter is mostly ignored while being really important. Not having default qualities of a log object is good on one hand but on the other hand the filtering is much harder. 

In SystemLogger we didn't go far enough at first. The Log class contained level and such. That was the reason for me to split it into BasicLog consisting of timestamp and a message object and Log which contains the extra qualities.

My problem with such approach is that it forces me to create hierarchy of log events as subclasses of base log component. 

Imaging that my application already provide hierarchy of events but they have no timestamps. How to log them? Should I use some WrapperSignal? 

Now imaging that application uses some library which provides events too. But this events are log entries themselves. What I will see in my logs? 

I will see mix of WrapperSignal's and normal events. It would be not easy to analize such log.

That's why I want unified log entries. I would model it with single class LogEntry which nobody needs to subclass. It would contain logging domain information: timestamp, importance level, user message and whatever. And it would have content property to keep logging object. So our tools can rely on this structure to make it easy to work with logs. And when anybody will look at particular log he will be sure that logging object is inside "content" variables of each record

-- 
Robert
.  ..   ...    ^,^

Hi,



Yes.

> Even if you could say that a timestamp is part of the logging domain it is not said if that timestamp needs to be part of the log object or the logger consuming this object.

This is a good point. I still see it closer to the event than to the logger.

> This question arises for every quality of a logging object. Even the logging level could be some behavioral quality that a logger matches to log levels. Contrary to this is logging thisContext which has to be done in the log object.

Yes.

I think it would be worthwhile to think about a composition mechanism. We could potentially use decorators for capturing extra information in the log event object.

> I think the hard part is the way of distribution of log objects and filtering of them. While the former is being discussed with Beacon the latter is mostly ignored while being really important. Not having default qualities of a log object is good on one hand but on the other hand the filtering is much harder.

I agree that we would benefit from an instance-based filtering mechanism, but I do not see why this is harder in Announcement. However we do it, it can be added to Announcements and it is available for all purposes (not just logging). Maybe I am missing something.

> In SystemLogger we didn't go far enough at first. The Log class contained level and such. That was the reason for me to split it into BasicLog consisting of timestamp and a message object and Log which contains the extra qualities. Nowadays I think you should be able to use any object as log object. The provided classes are just helpers. A composed object that has timestamp, level and a message object is a good utility but not a requirement. We need to support all of these. And so I would object against putting a lot of protocol in the Object class. In SystemLogger you have
>
> Object>>#asLog
> ^ self class newLog message: self

One thing that I think is misleading (I remember it took me some minutes to wrap my head around it) is the way SystemLogger uses the term “log”. In English, log denotes all entries (a log book), but in SystemLogger it is used to denote one event.

In any case, having an as* pattern (like it exists in Beacon) is the way to go.


> Object class>>#newLog
> ^ self logClass new
>
> Object class>>#logClass
> "Hook supporting the redefinition by object of their associated log.
> When using myObject asLog emit, the logClass will be used and myObject will be passed as message argument."
>
> ^ Log

This is another thing that is different from Beacon. I see the logging as a description of an event that is worthwhile capturing. This event has a strategy to record things. For example, when you capture an exception you might want to capture the complete context including the sender objects, or just the methods from the stack. This decision is tied to the Exception, but depends on the logging place. That is why I think we should not invest much in the pattern of hardcoding the strategy with the object. So, from this point of view, I would not want to pursue #logClass.


Yes.


> So to me the discussion about Log classes is not very helpful. We can have dedicated log classes like the stack capturing one but also one that is composed of the message object and certain qualities. If you would have a WrappedSyslogSignal you can have a log object that is composed and syslog aware by providing log levels.

I would actually like to invest in building a composition mechanism. This would allow us to compose logging objects with the information we would like to have.


> Again I think the hard part is to have flexible logging and still be able to filter it. I would like to be able to attach a handful of loggers and be sure the loggers get the right set of log objects they are interested in.

Do you have a concrete set of examples that you would like to see working? I think it would be useful to have a set of these concrete use cases to catch different design decisions against them. I have some cases and I will try to summarize them, but after the release of Pharo.

Cheers,
Doru


> Norbert
>  
>
>
>
>

--
www.tudorgirba.com
www.feenk.com

"If you can't say why something is relevant,
it probably isn't."

what I can tell you is that I do not like the API I did for extending Log in SystemLogger.

I will try to read your long email.

Now I have the impression that wrapping an object in the log could be a way to offer extensibility.

Hello.

I resumed discussion about SystemLogger and Beacon here http://forum.world.st/What-the-state-of-unifying-Beacon-with-SystemLogger-td4890684.html. 

I plan to unify both approaches by saving traditional terminology from SystemLogger and cool features from Beacon.

Let's think about logging API to log any object in the system. Most natural way is just send message #log to object itself:

anObject log

It would be nice replacement for Object>>logCr.

But when we log some information we usually want to log it with little remark, importance level and (most important) timestamp. This information is kind of standard for logging domain. But it requires much more methods for logging API.

So we need extra information to put together with objects:

1. timestamp
2. user message
3. importance level (debug, info, error, etc.)
4. whatever (process hash, process name for example)
5. sometimes it can be needed to put in log something different than object itself. (for example it can be just copy of object to not change state of log entry during app lifetime)

Here is possible API based on Object extensions. It has drawbacks but it is good to think about it too:

"it will put anObject in logs with default #info level"

anObject log 

"it will put anObject in logs with default #info level and given user message"

anObject logWith: 'something interesting was happened with anObject' 

 "inside block we can put any logging domain information from application and also override content by specific representation"

anObject logBy: [:logEntry |

      logEntry message: 'something interesting to be saved with our object'

      logEntry content: anotherObject] "here logs with interest about anObject will receive logEntry with anotherObject instead of anObject" 

And similar for different kind of levels:

anObject logForDebug.

anObject logForDebugWith: 'some debug message'

anObject logForDebugBy: [:logEntry | ]

anObject logAsError.

anObject logAsError: 'object computation was wrong'

anObject logAsErrorBy: [:logEntry | ]

And most general:

anObject logAs: LogLevel warn

anObject logAs: LogLevel warn with:  'something interesting'

anObject logAs: LogLevel warn by: [:logEntry | ]

And in case of classic logging with strings only first expressions would be used:

'some info message' log.

'some debug message' logForDebug

'some error message' logAsError

'some warn message' logAs: LogLevel warn

Problem with this approach: it pollutes Object with 12 extra methods and it can be more. So maybe it is better to use current SystemLogger API based on class Log: 

Log info: anObject

Log info: anObject as: 'computation result'        "as example"

Log info: anObject as: [:logEntry | 

logEntry message: 'something interesting to be saved with our object

logEntry content: anotherObject]

Log error: anObject

Log error: anObject as: 'computation was wrong''

Log error: anObject as: [:logEntry | ]

Comparing to original SystemLogger versions I separate user message from object content. It makes possible to log any object with extra user message.

But anyway it not feels very well IMHO. And it requires three methods for each log level. Maybe we can put this methods into LogLevel itself:

Log info add: anObject

Log info add: anObject as: 'computation result'

Log info add: anObject as: [:logEntry | 

logEntry message: 'something interesting to be saved with our object

logEntry content: anotherObject]

Log error add: anObject

Log error add: anObject as: 'computation was wrong''

Log error add: anObject as: [:logEntry | ]

And we can make short version for default logging level (which can be object specific):

Log add: anObject

Log add: anObject as: 'computation result'

Log add: anObject as: [:logEntry | ]

That's all. I hope we can produce best suitable API for object logging. Then we can think how to adopt SystemLogger or Beacon for it.

Also think about this API in context that we can register specific loggers for specific objects and specific importance level.

Best regards,

Denis

This type of usage should be discouraged in my opinion. We should instead encourage people to use typed logging signals, like we should also discourage people from using
        self error: ‘a magic string here’.


> But when we log some information we usually want to log it with little remark, importance level and (most important) timestamp. This information is kind of standard for logging domain. But it requires much more methods for logging API.
> So we need extra information to put together with objects:
>       • timestamp
>       • user message
>       • importance level (debug, info, error, etc.)

Please do not do that. This might make sense for C or Java (although it does not), but we have objects and we should filter based on those without relying on a rigid system based on random levels. Please.

Before I start to think about logging I was agree with you. Now I am not. This kind of information belongs to logging domain. It can be retrieved from application objects as default values but at the end it should be explicit part of log entries. We can read it in logs for every record to realize when and why object was added to log, what this record is about.

But denis why this is not for a certain kind of subclass
You have Log with the minimal information (timestamp and an object)
then you can have logger with levels and other.

And you say let's replace this "log object context" information with first class entities "typed signals". It means that for any possible case when I want to put something in log I should create class for new signal. It's just not practical.

why?
MySpecialLog
    ...
    emit

Beacon introduce WrapperSignal to solve it. But it only provides target and timestamp. What I should do if I want to put little remark for my object? And what if I want to put little remark for ThisContextSignal?

My idea that logging should be as simple as possible and we not need another "everything is signal" concept here: it is restriction. Everything is object. And every object should be able to log.

In the minimalLog

MinimalLog
    object: MyCoolObject new;
    emit

no need of message

And about random log levels. Their purpose is to mark log entries with importance level which is useful to explore logs.

Imaging we have system which produce some events and we log them. (My and your approaches allow it. Only difference that in my approach this event will be part of log entry (as composition) and with your approach this event will be log entry itself).

Now imagine that we need to explore some problem situation when particular events are appeared but they should not. I would try to find wrong places in code where events can be signalled and I would log them their.

With my approach I will log them with specific importance level (#warning) and specific message to distinguish them from normal events. With my API it is super easy.

With your approach I will need to create new classes to signal this situation. 

Also my approach allows me to configure in advance my application to put warnings in separate log. So I will not need to change app configs to simplify experiment. I will just deploy new code with extra logging and wait results in ready to use log. 

My proposals are not opposite to your. I just not put extra restrictions. Beacon can be based on top of it but not vice versa.

I must confess I cannot follow you completely. What we were/are talking about is that the assumption a logging entry needs timestamp, log level and such is not appropriate. If you have legacy syslog style logging in mind it appears natural but for a lot of use cases it is not. Even if you could say that a timestamp is part of the logging domain it is not said if that timestamp needs to be part of the log object or the logger consuming this object. This question arises for every quality of a logging object. Even the logging level could be some behavioral quality that a logger matches to log levels. Contrary to this is logging thisContext which has to be done in the log object.

I think the hard part is the way of distribution of log objects and filtering of them. While the former is being discussed with Beacon the latter is mostly ignored while being really important. Not having default qualities of a log object is good on one hand but on the other hand the filtering is much harder. 

In SystemLogger we didn't go far enough at first. The Log class contained level and such. That was the reason for me to split it into BasicLog consisting of timestamp and a message object and Log which contains the extra qualities. Nowadays I think you should be able to use any object as log object. The provided classes are just helpers. A composed object that has timestamp, level and a message object is a good utility but not a requirement. We need to support all of these. And so I would object against putting a lot of protocol in the Object class. In SystemLogger you have

Object>>#asLog

^ self class newLog message: self

Object class>>#newLog

^ self logClass new

Object class>>#logClass

"Hook supporting the redefinition by object of their associated log.

When using myObject asLog emit, the logClass will be used and myObject will be passed as message argument."

^ Log

So assuming the Log class would not contain log levels but SysLog would do you could easily override #logClass in your domain object and use it this way

MyDomainClass class>>#logClass

^ SysLog

myDomainObject asLog

warning;

emit

This way we do not need to pollute Object with a lot of methods that are tight to one use case. The call to #warning could be something else that only depends on the Log class you want to use. 

So to me the discussion about Log classes is not very helpful. We can have dedicated log classes like the stack capturing one but also one that is composed of the message object and certain qualities. If you would have a WrappedSyslogSignal you can have a log object that is composed and syslog aware by providing log levels. Again I think the hard part is to have flexible logging and still be able to filter it. I would like to be able to attach a handful of loggers and be sure the loggers get the right set of log objects they are interested in.

Hi norbert

I agree.
I have the impression that in SystemLogger I would change message: into object: in Log and remove all the extension API I tried to design.
This way people can just pass the object they want if they want still to have the object wrapped into a Log instances.
I think that Log instances and subclasses would be nice to have specific behavior (like menu actions when we want to manipulate logs).

For example, I would like to have a tool looging all the methods that I did not define during a prototype session and after I can click on them and say "define skeleton"
and boum I get a skeleton for all the methods inside their respective classes.

Stef

Hi Norbert

2016-04-27 10:43 GMT+02:00 Norbert Hartl <[hidden email]>:

So assuming the Log class would not contain log levels but SysLog would do you could easily override #logClass in your domain object and use it this way

MyDomainClass class>>#logClass

^ SysLog

myDomainObject asLog

warning;

emit

This way we do not need to pollute Object with a lot of methods that are tight to one use case. The call to #warning could be something else that only depends on the Log class you want to use. 

There is one problem with this approach when we split preparation and emitting of log object. It will always produce garbage. If no logs will have interest in myDomainObject or #warning-level messages application will continue create log entries.

Denis I do not get what you mean with the sentence above.

I think it is important to minimize cost of logging when nobody have interest on particular event. If debug-level log is disabled then no garbage should be created. If stack traces log is disabled then no stack information should be retrieved anywhere.

To achieve this we should create log entry instances only when we will find any logs for them. It imposes restriction on possible API. At point when we are ready to log something we should have all information which can be part of filter. So if we want to filter logs by domain objects and log-levels we need both parameters in one message send. Then we can ask every registered log for interest about both of them. And only when we will find any one we will create log entry instance for them.

2016-04-27 10:43 GMT+02:00 Norbert Hartl <[hidden email]>:

I must confess I cannot follow you completely. What we were/are talking about is that the assumption a logging entry needs timestamp, log level and such is not appropriate. If you have legacy syslog style logging in mind it appears natural but for a lot of use cases it is not.

Could you provide example where it is not?

 

Even if you could say that a timestamp is part of the logging domain it is not said if that timestamp needs to be part of the log object or the logger consuming this object. This question arises for every quality of a logging object. Even the logging level could be some behavioral quality that a logger matches to log levels. Contrary to this is logging thisContext which has to be done in the log object.

I think the hard part is the way of distribution of log objects and filtering of them. While the former is being discussed with Beacon the latter is mostly ignored while being really important. Not having default qualities of a log object is good on one hand but on the other hand the filtering is much harder. 

In SystemLogger we didn't go far enough at first. The Log class contained level and such. That was the reason for me to split it into BasicLog consisting of timestamp and a message object and Log which contains the extra qualities.

My problem with such approach is that it forces me to create hierarchy of log events as subclasses of base log component.

not necessary
we could have Log being a potential wrapper.

Imaging that my application already provide hierarchy of events but they have no timestamps. How to log them? Should I use some WrapperSignal? 

Now imaging that application uses some library which provides events too. But this events are log entries themselves. What I will see in my logs? 

I will see mix of WrapperSignal's and normal events. It would be not easy to analize such log.

That's why I want unified log entries. I would model it with single class LogEntry which nobody needs to subclass. It would contain logging domain information: timestamp, importance level, user message and whatever. And it would have content property to keep logging object. So our tools can rely on this structure to make it easy to work with logs. And when anybody will look at particular log he will be sure that logging object is inside "content" variables of each record