perfsonar-dev - Re: [pS-dev] (SYS)LOG messages generated by the pS services?

Subject: perfsonar development work

List archive

Re: [pS-dev] (SYS)LOG messages generated by the pS services?

From: Fausto Vetter <>
To: Martin Swany <>
Cc: "Luchesar V. ILIEV" <>, "" <>, Michael Bischoff <>, Stijn Melis <>, Jochen Reinwand <>, , Nicolas Simar <>,
Subject: Re: [pS-dev] (SYS)LOG messages generated by the pS services?
Date: Fri, 25 Apr 2008 17:58:01 +0100

Hi,

Service Desk is fine to use eventtypes, once they can be translated to real events that happens to the system. My concern, thinking now, is that eventtypes end up to be suitable to define the overall activities, like a SetupDataRequest for eventtype utilization, but for logging eventtypes are not as powerful. You might need details like xml database connection or other internal event that are not really perfSONAR events, but are events used to provide a perfSONAR service.

What do you think? :-)

Fausto

Martin Swany wrote:

Speaking of "interesting turns", I also find it ironic that attribute/value
pairs are too complicated/hard to read, but that we might consider
XML in there.... :-)

martin

On Apr 25, 2008, at 5:44 AM, Luchesar V. ILIEV wrote:

Hi guys,

This discussion takes interesting turns. :) Well, "interesting", because I came out with the idea of using syslog as an "evolutionary" step. My expectation was that most developers had been using syslog anyway, so it seemed only natural to use this for centralized monitoring services as well.

What I had in mind was that with syslog, being a relatively simple (yet, quite effective, as we know) system, we could concentrate on the contents of the entries, rather than on the format (which should have been more or less standard... or so I thought :D.)

Don't get me wrong, I'm not saying the format proposals are unwelcome: quite on the contrary; I'm just making an interesting observation. Now, specifically for the XML, it IS very interesting, because our next step will (almost certainly) be extending the EchoRequest (and, respectively, the EchoResponse) messages.

Still, however, my view is that at this stage we should concentrate on making clear _what_ are we going to have in those log entries/messages. To me, the notion of "format" at the moment is more in the sense of how it will be nice to have it presented in the logs, in order for it to be easily comprehensible by humans.

Of course, I can see the strong points in the "plan ahead" approach, but what I'm mostly worried about is the time: we have 30th of April imposed by Nicolas as the deadline to have a proposal for the syslog entries format. And going back to the syslog, perhaps putting XML in it will (actually: definitely will) hurt the legibility.

So, while we should certainly keep in mind the interesting suggestions that are being made, I would suggest to concentrate on what exactly will the log entries contain and look like.

Fausto, you've set up very nice pages on the Wiki, thanks. :) I have a few comments, but I'll present them in a separate mail. Concerning the fine format you proposed however, I'm still lost about the questions I raised earlier, I'm afraid:

> [SERVICE_TYPE] RESULT.ACTION 'DESCRIPTION'

1) Do we have a common agreement on the SERVICE_TYPEs abbreviations?

2) RESULT should be fairly straightforward, I guess, but how about ACTION -- I'm afraid I don't understand what is going to be recorded there exactly. To put it another way -- are the ACTIONs going to be fairly standard (in fact: enforced as standard?)

Cheers,
Luchesar

Fausto Vetter wrote:

Hi,
This mixed format seems to be interesting... once the whole service is XML based... It allows free format plus fixed fields. The only thing I see is that what needs to be agreed, if going in this direction, is the xml fields wanted and the format or even the value of the data inside, because the idea is to be able to put it in a SQL database for trying to get some useful information about the service usage and/or performance. It is basically a template for the log, but using XML tags to demark the fields, isnt it?
Cheers,
Fausto
Michael Bischoff wrote:

hi all,

I'm currently occupied with other things so I missed the video conference but have we looked
at the xml-mixed way of things?

http://www.w3schools.com/schema/schema_complex_mixed.asp

(timestamp is provided by default so we know when it failed.)
Task started at <time>22:00</time> <date>2008-04-25<date> with id <id>612</id> failed.

if you do console logging run it though a filter that removes (meta)tags:
Task started at 22:00 2008-04-25 with id 612 failed.

off course writing a parser that handles the format is trivial; but we can actually reuse
existing libraries and save even more time.

the api can be straight forward for general types:
log("Task started at", date, ...
and just a little painfull with non-general types.
log("Task started at", date, "with", tag("id",621), "failed.");

void log(Object... args) {
StringBuilder message = ...
for(Object arg : args) {
if(<arg is an String>) {
message.write(arg); -> just write it
} else if(<arg is an Date>) {
... parse date with time and date tags ...
}
}

the advantage of mixed type like approach is that you can add as much metadata as you want(as
opposed by the fixed format) while it maintains readable even with the tags(although a filter
should be easy(even if a filter isn't implemented easily writing a log viewer is trivial.))
as opposed with the key=value format.

other advantage is that you avoid some of the standardisation hell: default(/general) types
should be easy to maintain and non-default(/general) can be ignored(you only lose some meta
data if you strip it.) while in general the message is still intact(as opposed fro mthe
key=value approach.

just some thoughs.

kind regards,

Michael Bischoff

Hi guys,

I fully concur too. Just like Jochen, I also have strong preference
towards the typical syslog format of the entries. Fausto's suggestion thus seems very nice.

I'd just like to ask a couple of questions:

1) Do we have a common agreement on the SERVICE_TYPEs abbreviations?

2) RESULT should be fairly straightforward, I guess, but how about
ACTION -- I'm afraid I don't understand what is going to be recorded
there exactly. To put it another way -- are the ACTIONs going to be fairly standard (in fact:
enforced as standard?)

Cheers,
Luchesar

Stijn Melis wrote:

Hi,

this format presented by Fausto looks very good to me also. It is easy to read, and it
clearly states what needs to be said.

cheers,

Stijn

Jochen Reinwand wrote:

Hi,

OK for me! I do not really like CSV also ;)
It's really an advantage to have readable, "normal" syslog entries.
Not everybody wants to set up a centralised parsing after installing
only a simple perfSONAR service.

Jochen

On Thursday 24 April 2008 10:49, Fausto Vetter wrote:

Hi,

I like the idea of having a format, but I don't like the idea of just
CSV (comma, semi-comma, etc) format. It becomes easy to parse but not
easy to read. It would be better for example:

[pS-XML-LS] success.ls.remove 'Lookup info registered with key
http://stout.pc.cis.udel.edu:8080/services/RRDMA has been removed!'

where:

[SERVICE_TYPE] RESULT.ACTION 'DESCRIPTION'

Other fields like date & time and source are inherent to syslog format.

What do you think?

Fausto

Jochen Reinwand wrote:

Hi all,

I don't think that the EGEE guidelines are "wrong". They are not even
unusable for us! But I have the feeling that these key/value pairs tend to grow to a
standardisation horror. Parsing is easy! I'm quite sure Fausto is thinking about
analysing the syslog via Perl. Parsing key/value pairs in Perl is like writting "Hello
world!" in C. Eh, OK it's even easier... But I fear that we will get into a lot of
different key/value pairs that will be very hard to interpret (the necessary second
step after parsing). I'm forseeing log lines like these:

my-service-error=12345 xyz-stack=pop \
time=3-quarters-to-4-hours-after-local-midnight

Using a fixed format will perhaps prevent such a misuse. I see
something like a decision tree:

system;Cannot create pid file

perfSONAR;success.ls.remove;Lookup info registered with key \
http://stout.pc.cis.udel.edu:8080/services/RRDMA has been removed!

hades;database;No data found

Here "system" means related to perfSONAR independent errors comming
from typical system interaction (e.g. daemon creating a pid file). With "perfSONAR"
prefix typical perfSONAR/NM-WG status messages are logged. The idea here: Write to
syslog what the user sees in the response. The last example is a "background system"
related error. Most perfSONAR services use some tools or databases in the background.
It is most
likely usefull to log errors in this subsystems this way.

Once again: This can also be done using key/value pairs, but I fear to
much freedom here...

greetings, Jochen

On Wednesday 23 April 2008 20:26, Martin Swany wrote:

Hi all,

I think that the overhead of the best practices format is justified by
the gains that Brian mentioned. Also note that the log format is analogous to the
NM-WG format in that it has a hierarchical
event names (eventType). I think there are some obvious wins that come from having
the same namespaces used in the log messages and in the result codes.

best, martin

On Apr 23, 2008, at 12:45 PM, Fausto Vetter wrote:

Hi,

Thats a good point. It needs to have a grammar otherwise it becomes
hard to parse and get some useful information from it. Putting in a database is a
step forward to go in some time, thats why we are gonna setup a syslog server.

Cheers,
Fausto

Brian Tierney wrote:

Luchesar:

One of the main advantages of a 'best practice'-like format is that
if you think there might be a time you'd want to put these logs into a database,
then the logs must have some grammar, and not be totally freeform.

Im not sure there is an immediate use case for putting perfSONAR
logs into a database, but it might be good to make sure that the logs all follow
the same grammar in case such a use case arises in the future.

One possible use case I can think of is the following.

Imagine that every perfSONAR service generated a syslog message
logging each client connection. If the syslog messages where collected and
stored in a database, it would be very each to make queries such as 'tell me
the 10 top clients of perfSONAR services last week'.

Clearly a log message that looked like something like this:

event=org.perfSONAR.MA.connect client=A.B.C.D request=RetrieveData

would be much easier to parse and insert into a database that one that might
look like this:

'received request for data from client x.y.w.z'

Something to consider.

Cheers.

Luchesar V. ILIEV wrote:

Hi Brian, Jochen, all,

First of all, Brian, thank you very much for providing a pointer
to this very interesting document. It'll certainly be helpful in our efforts
within perfSONAR.

At the same time, I have to agree with Jochen on most of his
points. Indeed, one of the reasons to use syslog is exactly the fact that it
already does provide standard approach to some of the issues.

The "key/value" pairing also does not appeal very much to me
(although I'm sure it is chosen for very good reasons in the
context of the Grid Troubleshooting project.) On the other hand, the fixed
positioning of the data is something that will depend very much on what
information is there going to be.

* * *

For that latter reason, I'd like to kindly ask once more the
developers of the pS services to provide me with at least a few representative
examples of messages that could be generated during the operation of their
service. Otherwise I'll have to base my proposal on purely theoretical
considerations -- perhaps not the best way to go.

* * *

Brian, Jochen, once again many thanks for your feedback.

Cheers,
Luchesar

Jochen Reinwand wrote:

Hi Brian, hi all,

I think this Best Practice is perhaps too complex for us. Things
like timestamp and level are already part of the syslog functionality
anyway. For perfSONAR we already have error codes, that can be used more
or less directly also for syslogging. I would really recommend this! This
way the syslog receives the same messages and codes as the user does via
the perfSONAR response. There are some message that do not necessarily
issue a perfSONAR error response. I think these are all typical UNIX system
error like "File not found", "Execution failed" and so on. These should be
send to syslog in a very simple form to distinguish them from the perfSONAR
errors. I'm not sure whether a key value pair style string is really
handy. Most tools don't use such a format for syslogging. A string with
fixed positions with fixed meanings is normally easier to handle and makes
it easier to enforces a common discipline.

regards, Jochen

On Sunday 20 April 2008 17:40, Brian Tierney wrote:

Hi all:

I am working on a Grid Troubleshooting project where for logging
we agreed on a syslog format where everything is 'name=value' pairs. We
felt that this was the best compromise of easy to parse and easy to read.

We also said that each log line should have a required
'event=eventname', where eventname should be similar to a java
class name.

I recommend that perfSONAR logs use this format as well.

For more information.

http://www.cedps.net/index.php/LoggingBestPractices

This format is the same as the EGEE "Middleware Security Audit
Logging
Guidelines": http://edms.cern.ch/document/793208

Cheers.

Luchesar V. ILIEV wrote:

Hi guys,

This mail is addressed to all pS service developers. As you
know, last week in Zagreb we discussed the issues of monitoring the
deployed pS services to ensure they are operating as intended, and
really serving the end-users' requests up to the users' satisfaction.

As a next step in this process (having used so far ICMP, HTTP
GET, and
perfSONAR EchoRequest/EchoResponse messages,) in order to achieve more
in-depth monitoring, which could, in turn, provide a more true- to-life
view on the functioning of the services, we've decided in Zagreb to
utilize the well-known and widely-used mechanism of sysloging.

I've the task to prepare a proposal for a common format of the
syslog messages, or (depending on your feedback) at least some
guidelines, which would ensure having consistency amongst the different
service's messages' general structure.

Therefore, I'd like to ask you to provide me either with a full
list of the possible messages that the service you're working on could
eventually write to the log, or provide me with information on the
structure of the (different types of these) messages.

It could be helpful to have also some indication about the
severity of each message (from your point of view, of course): e.g.,
debug, information, warning, error, critical failure, etc. As decided in
Zagreb, you have to synchronize this with the Service Desk --
if you could do this beforehand, it would be great. If not, I would be OK
with your own (from service developer's point of view) classification.

I'll appreciate if you could send me your feedback before the
end of next business week: that is, 25th of April inclusive.

If there's something unclear in my e-mail and specifically
about my request, please do contact me.

Many thanks in advance,

Cheers,
Luchesar

Re: [pS-dev] (SYS)LOG messages generated by the pS services?, (continued)

List archive

Re: [pS-dev] (SYS)LOG messages generated by the pS services?