Menu
▾
▴
naviserver-devel
|
From: Zoran V. <zv...@ar...> - 2006-06-22 17:31:10
|
Hi!
I have a need of adding more features to the existing
ns_log facility.
We have tons of code emitting ns_log messages into the
server logfile. But as everything ends up in one single
file, it is somethimes extremely difficult to analyze it
as you may end up in staring at 100'000s of lines.
Our application generates jobs. Each jobs uses modules
and modules log things (i.e calls ns_log). What we'd
need is a way to "teach" the ns_log command that it is
emitting log in the context of the job X and perhaps
route log data to a specific log file. This way we could
group the log entries that correspond to one job into one
per-job file. This is far easier to analyze and debug, of course.
What I have in mind is a kind of push/pop mechansim where
I could do something like:
ns_logctl push <mylogprocedure1>
...
ns_logctl push <mylogprocedure2>
...
ns_logctl pop
...
ns_logctl pop
This would instruct the ns_log facility to invoke registered
callbacks one by one. Each callback will do something and
all will eventually end up at the low-level common-denominator
being the current log file. Every callback might/could signalize
two states: continue or break. According to that, the next
registered call will be called (continue) or not (break).
The callbacks themselves would be just Tcl code which will be
prepared by the caller and "ns_logctl push"'ed on the stack
of registered handlers.
Now, in order to do that I will have to modify ns_logctl command
and modify internal operation of ns_log to walk in LIFO fashion
list of registered handlers and invoke each one of them in
succession.
Are there any better ideas how to achieve this? If not, is everybody
OK with the proposed change?
Cheers,
Zoran
|
|
From: Vlad S. <vl...@cr...> - 2006-06-22 18:25:47
|
Go ahead if it will not break "simple" logging and ns_log behaviour Zoran Vasiljevic wrote: > Hi! > > I have a need of adding more features to the existing > ns_log facility. > > We have tons of code emitting ns_log messages into the > server logfile. But as everything ends up in one single > file, it is somethimes extremely difficult to analyze it > as you may end up in staring at 100'000s of lines. > > Our application generates jobs. Each jobs uses modules > and modules log things (i.e calls ns_log). What we'd > need is a way to "teach" the ns_log command that it is > emitting log in the context of the job X and perhaps > route log data to a specific log file. This way we could > group the log entries that correspond to one job into one > per-job file. This is far easier to analyze and debug, of course. > > What I have in mind is a kind of push/pop mechansim where > I could do something like: > > ns_logctl push <mylogprocedure1> > ... > ns_logctl push <mylogprocedure2> > ... > ns_logctl pop > ... > ns_logctl pop > > This would instruct the ns_log facility to invoke registered > callbacks one by one. Each callback will do something and > all will eventually end up at the low-level common-denominator > being the current log file. Every callback might/could signalize > two states: continue or break. According to that, the next > registered call will be called (continue) or not (break). > > The callbacks themselves would be just Tcl code which will be > prepared by the caller and "ns_logctl push"'ed on the stack > of registered handlers. > > Now, in order to do that I will have to modify ns_logctl command > and modify internal operation of ns_log to walk in LIFO fashion > list of registered handlers and invoke each one of them in > succession. > > Are there any better ideas how to achieve this? If not, is everybody > OK with the proposed change? > > Cheers, > Zoran > > Using Tomcat but need to do more? Need to support web services, security? > Get stuff done quickly with pre-integrated technology to make your job easier > Download IBM WebSphere Application Server v.1.0.1 based on Apache Geronimo > http://sel.as-us.falkag.net/sel?cmd=lnk&kid=120709&bid=263057&dat=121642 > _______________________________________________ > naviserver-devel mailing list > nav...@li... > https://lists.sourceforge.net/lists/listinfo/naviserver-devel > -- Vlad Seryakov 571 262-8608 office vl...@cr... http://www.crystalballinc.com/vlad/ |
|
From: Zoran V. <zv...@ar...> - 2006-06-22 20:10:29
|
Am 22.06.2006 um 20:26 schrieb Vlad Seryakov: > Go ahead if it will not break "simple" logging and ns_log behaviour It wont! But as Gustaf already suggested, one can wrap the ns_log in Tcl and do whatever one will from the Tcl level anyway. I will have to see if this will be sufficient. If yes, then I'll need not touch the C-level code, which is great as it won't destabilize the code. OTOH, I may find it not feasible in which case I will have to dig inside. In that case, I will add to and not remove nor change the default behaviour that everybody is using This is clear. Cheers, Zoran |
|
From: Zoran V. <zv...@ar...> - 2006-06-25 08:00:20
|
Am 22.06.2006 um 22:10 schrieb Zoran Vasiljevic: > But as Gustaf already suggested, one can wrap the ns_log > in Tcl and do whatever one will from the Tcl level anyway. > I will have to see if this will be sufficient. It's not :-( The problem is: we also have whole lotta C-modules calling Ns_Log() C-API hence pure wrapping of the Tcl ns_log call will just partly help. I have been looking at the current code and indeed there are hooks in the log machinery to overload the log and log-flush calls. But it is either/or stuff. So you either use your own version OR you use the built-in version. What I would like to do is to expand this to push/pop any number of calls and execute them in LIFO fashion. The ns_logctl can be used to push the log and flush functions implemented as Tcl callbacks and there should be equivalent C-API for that as well. I will examine this in detail today and see if I can have a working version to check out. This is of very high importance to us hence you may count on seeing some results pretty soon... Cheers Zoran |
|
From: Gustaf N. <ne...@wu...> - 2006-06-25 09:30:28
|
Zoran Vasiljevic schrieb: > Am 22.06.2006 um 22:10 schrieb Zoran Vasiljevic: > > >> But as Gustaf already suggested, one can wrap the ns_log >> in Tcl and do whatever one will from the Tcl level anyway. >> I will have to see if this will be sufficient. >> > > It's not :-( > > The problem is: we also have whole lotta C-modules > calling Ns_Log() C-API hence pure wrapping of the > Tcl ns_log call will just partly help. > Well, i would not base the whole design decision on this fact, since also from the c-level one could call the tcl/xotcl log functions. As you said, speed should not be a major issue, having a flexible log environment with easy filtering for sessions/users/modules/... and different levels of detail is very conveniant. This should not be an argument against your proposal, since it won't prohibit to have the tcl-layer-flexibility on top of it as well. My point was not to rush to early to c.... -gustaf |
|
From: Zoran V. <zv...@ar...> - 2006-06-25 12:08:36
|
Am 25.06.2006 um 11:30 schrieb Gustaf Neumann: > Well, i would not base the whole design decision on this fact, since > also from the c-level one could call the tcl/xotcl log functions Well, this is not the only reason (see below). I also believe it is cleaner to have C-code not dependent (if possible) to any Tcl code. By getting apropriate "hooks" into the log facility, one can handle just about any situation with relative ease being it just C or just Tcl or a combination. At the moment, the way of expanding the log facility is pretty inflexible. Currently you can overload internal log and flush calls only. If one module redefines those log calls, another module can junk its modifications by plugging into the same hook. Also, the "default" operation of the log-facility is from that point, entirely dependent on the overloading module. This is not very nice and the idea is to improve on that as well. I will however not change that behaviour as I do not really know wether somebody is using it or not. What I'd do is to change the default way of handling the log entries by adding a list of callbacks one can add and/or remote to/from. The callbacks themselves can be written in C or in Tcl similar to the filter callbacks we already use. This way, the current log processing (a call to write(2...) will be implemented as yet-another-callback so the entire beast will be completely generic. By addind more callbacks one will not influence/replace the default processing, rather expand it! I hope to get some code pretty soon and I will post diffs to the list. This will then be much easier to understand. Cheers Zoran |
|
From: Stephen D. <sd...@gm...> - 2006-06-25 10:48:45
|
What happens if you push but don't pop, maybe an uncaught error? The very first change in aolserver cvs after being opened was to remove the modlog api. Like most logging implementations, it took both a facility and a level. Ns_Log only takes a level. How about adding a 'facility' arg back? On 6/22/06, Zoran Vasiljevic <zv...@ar...> wrote: > Hi! > > I have a need of adding more features to the existing > ns_log facility. > > We have tons of code emitting ns_log messages into the > server logfile. But as everything ends up in one single > file, it is somethimes extremely difficult to analyze it > as you may end up in staring at 100'000s of lines. > > Our application generates jobs. Each jobs uses modules > and modules log things (i.e calls ns_log). What we'd > need is a way to "teach" the ns_log command that it is > emitting log in the context of the job X and perhaps > route log data to a specific log file. This way we could > group the log entries that correspond to one job into one > per-job file. This is far easier to analyze and debug, of course. > > What I have in mind is a kind of push/pop mechansim where > I could do something like: > > ns_logctl push <mylogprocedure1> > ... > ns_logctl push <mylogprocedure2> > ... > ns_logctl pop > ... > ns_logctl pop > > This would instruct the ns_log facility to invoke registered > callbacks one by one. Each callback will do something and > all will eventually end up at the low-level common-denominator > being the current log file. Every callback might/could signalize > two states: continue or break. According to that, the next > registered call will be called (continue) or not (break). > > The callbacks themselves would be just Tcl code which will be > prepared by the caller and "ns_logctl push"'ed on the stack > of registered handlers. > > Now, in order to do that I will have to modify ns_logctl command > and modify internal operation of ns_log to walk in LIFO fashion > list of registered handlers and invoke each one of them in > succession. > > Are there any better ideas how to achieve this? If not, is everybody > OK with the proposed change? > > Cheers, > Zoran > > Using Tomcat but need to do more? Need to support web services, security? > Get stuff done quickly with pre-integrated technology to make your job easier > Download IBM WebSphere Application Server v.1.0.1 based on Apache Geronimo > http://sel.as-us.falkag.net/sel?cmd=lnk&kid=120709&bid=263057&dat=121642 > _______________________________________________ > naviserver-devel mailing list > nav...@li... > https://lists.sourceforge.net/lists/listinfo/naviserver-devel > |
|
From: Zoran V. <zv...@ar...> - 2006-06-25 11:46:39
|
Am 25.06.2006 um 12:48 schrieb Stephen Deasey:
> What happens if you push but don't pop, maybe an uncaught error?
I was also thinking about:
ns_logctl register callback ?arg...?
ns_logctl unregister callback
This way the push/pop is avoided and the problem of non-symetric
usage is gone, as callbacks will be added/removed to/from a list
not a stack.
The callbacks themselves will be called in succession by the underlying
implementation. The very first (default, always present) callback will
be a call to write() as in the current implementation. This guarantees
that log entries will be written into the log file, as today.
Other callbacks may be called in FIFO or LIFO order (there are some
thoughts about that below...)
>
> The very first change in aolserver cvs after being opened was to
> remove the modlog api. Like most logging implementations, it took both
> a facility and a level. Ns_Log only takes a level.
>
> How about adding a 'facility' arg back?
Would that mean ns_log will be something like:
ns_log ?-facility whatever? severity arg ?arg ...?
??
Actually, at the moment I was not thinking about facilities although =20
it might
be considered as well. My primary motivation behind this is to get =20
better
*organization* of the existing log information (severity, message, =20
timestamp
process-id/thread-id).
At the moment we have everything line-wise in one log file. This is =20
good as
you always know where to look, and there is a time-related order =20
there as well.
But, disadvantage is: one can easily get lost if you have 100'000 of =20
lines of
log info generated by different modules all doing logs for the same =20
"job".
By adding some additional log "sinks" I can channel log information into
appropriate "per-job" log files. This retains the global log file but =20=
adds
more *order* by separating "job-related" logs into corresponding per-=20
job files.
For example:
proc joblog {level timestamp message jobId} {...}
set id the_job_id_or_handle
ns_logctl register joblog $id
So when somebody says:
ns_log info "This is the info"
the log facility will emit a log line into the log file
(as it does now), but will in addition call:
joblog info 1151234419:0000000 "This is the Info=10" =20
the_job_id_or_handle
Depending on the passed user argument(s) (in the above case
the_job_id_or_handle) the "joblog" will know what to do, i.e.
where and how to produce log entry.
The "timestamp" argument will include both seconds and microseconds
(we already have Tcl_Obj type for that).
When the callback is not needed any more, it can be removed
by calling:
ns_logctl unregister joblog
One can have any number of callbacks registered. All of them
will be entered in a list and invoked one after another
with the same level, timestamp and message arguments, but with
different user argument(s).
One additional thing we MAY do is to invent a callback return
value to signalize "continue" or "break" in the similar sense
as filters are doing. This way any callback can forbid lower
level callbacks to be invoked. This is just an idea and it
needs careful thinking though. For example: what does this mean
for the standard logfile sink? If an late callback returns break
would that cut-off the standard log sink or just registered
callbacks? Of course, this will require us to defined order of
invocation i.e. LIFO or FIFO as well...
I hope I managed to convey the *general* idea to you...
Cheers,
Zoran
|
|
From: Stephen D. <sd...@gm...> - 2006-06-25 13:10:52
|
On 6/25/06, Zoran Vasiljevic <zv...@ar...> wrote:
>
> Am 25.06.2006 um 12:48 schrieb Stephen Deasey:
>
> > What happens if you push but don't pop, maybe an uncaught error?
>
> I was also thinking about:
>
> ns_logctl register callback ?arg...?
> ns_logctl unregister callback
>
> This way the push/pop is avoided and the problem of non-symetric
> usage is gone, as callbacks will be added/removed to/from a list
> not a stack.
>
> The callbacks themselves will be called in succession by the underlying
> implementation. The very first (default, always present) callback will
> be a call to write() as in the current implementation. This guarantees
> that log entries will be written into the log file, as today.
> Other callbacks may be called in FIFO or LIFO order (there are some
> thoughts about that below...)
>
> >
> > The very first change in aolserver cvs after being opened was to
> > remove the modlog api. Like most logging implementations, it took both
> > a facility and a level. Ns_Log only takes a level.
> >
> > How about adding a 'facility' arg back?
>
> Would that mean ns_log will be something like:
>
> ns_log ?-facility whatever? severity arg ?arg ...?
>
> ??
>
> Actually, at the moment I was not thinking about facilities although
> it might
> be considered as well. My primary motivation behind this is to get
> better
> *organization* of the existing log information (severity, message,
> timestamp
> process-id/thread-id).
>
> At the moment we have everything line-wise in one log file. This is
> good as
> you always know where to look, and there is a time-related order
> there as well.
> But, disadvantage is: one can easily get lost if you have 100'000 of
> lines of
> log info generated by different modules all doing logs for the same
> "job".
> By adding some additional log "sinks" I can channel log information into
> appropriate "per-job" log files. This retains the global log file but
> adds
> more *order* by separating "job-related" logs into corresponding per-
> job files.
>
> For example:
>
> proc joblog {level timestamp message jobId} {...}
> set id the_job_id_or_handle
> ns_logctl register joblog $id
>
> So when somebody says:
>
> ns_log info "This is the info"
>
> the log facility will emit a log line into the log file
> (as it does now), but will in addition call:
>
> joblog info 1151234419:0000000 "This is the Info=10"
> the_job_id_or_handle
>
> Depending on the passed user argument(s) (in the above case
> the_job_id_or_handle) the "joblog" will know what to do, i.e.
> where and how to produce log entry.
> The "timestamp" argument will include both seconds and microseconds
> (we already have Tcl_Obj type for that).
>
> When the callback is not needed any more, it can be removed
> by calling:
>
> ns_logctl unregister joblog
>
> One can have any number of callbacks registered. All of them
> will be entered in a list and invoked one after another
> with the same level, timestamp and message arguments, but with
> different user argument(s).
>
> One additional thing we MAY do is to invent a callback return
> value to signalize "continue" or "break" in the similar sense
> as filters are doing. This way any callback can forbid lower
> level callbacks to be invoked. This is just an idea and it
> needs careful thinking though. For example: what does this mean
> for the standard logfile sink? If an late callback returns break
> would that cut-off the standard log sink or just registered
> callbacks? Of course, this will require us to defined order of
> invocation i.e. LIFO or FIFO as well...
>
> I hope I managed to convey the *general* idea to you...
Got it.
It might still be a good idea to add 'facility' as a parameter. e.g.
your registering a callback and passing an arg 'id'. Your callback is
distinguishing what to do depending on the arg -- it get's called no
matter what the level is.
If you add facility, you could:
ns_logctl register $facility $priority joblog ?arg ...?
The filtering would be done by the server, rather than the callback.
You're focusing on sinks here, but you need a way to distinguish what
goes where, and facility levels seem like such a standard thing. It
would enable you to turn on verbose logging for just one area of code,
which would reduce log spam.
Take a look at log4j by the apache project. This is very popular and
seems to have inspired a lot of imitators such as log4py, log4c etc.
Maybe log4c has a better API than the old Ns_ModLog stuff.
|
|
From: Zoran V. <zv...@ar...> - 2006-06-25 13:50:33
|
Am 25.06.2006 um 14:41 schrieb Stephen Deasey: > If you add facility, you could: > > ns_logctl register $facility $priority joblog ?arg ...? > > The filtering would be done by the server, rather than the callback. > You're focusing on sinks here, but you need a way to distinguish what > goes where, and facility levels seem like such a standard thing. It > would enable you to turn on verbose logging for just one area of code, > which would reduce log spam. > > Take a look at log4j by the apache project. This is very popular and > seems to have inspired a lot of imitators such as log4py, log4c etc. > Maybe log4c has a better API than the old Ns_ModLog stuff. In this case, the ns_log call will also have to change as in: ns_log facility severity arg ?arg...? or? If this is true, then I would not like to do that, as one of my main targets is: keep the changes to the existing code as minimal as possible. For example, I can wrap one of our internal procedures which calls 100's of other, which in turn already use ns_log (and Ns_Log()) to fill-in the log file: ns_logctl register backup_log [getjobid] backup [getjobid] ns_logctl unregister backup_log This way all ns_log's called between those two ns_logctl will emit log entries not only to the global server logfile but also where backup_log procedure will send them. I need not modify ANY other places in the code. Does this compute? Or did I misunderstand your idea? Cheers, Zoran |
|
From: Zoran V. <zv...@ar...> - 2006-06-25 14:34:16
|
Am 25.06.2006 um 14:41 schrieb Stephen Deasey:
>
> Take a look at log4j by the apache project. This is very popular and
> seems to have inspired a lot of imitators such as log4py, log4c etc.
> Maybe log4c has a better API than the old Ns_ModLog stuff.
>
I did. This is exactly what I thought: they use "kind of" facility
as a hierarchical thing, like some.log.thing which of course
requires you to obtain the logger which knows how to produce
log for some.log-thing and then use that logger to log the entry.
In procedural types of languages we'd need to
ns_log some-log.thing info "This is the info log"
but this would be backwardly incompatible and would mean total
departure of what we have now.
Consider this stupid little example:
proc add {a b} {
if {$a == 0 || $b == 0} {
ns_log warning "add: one argument is zero"
}
}
Whenever/whereever/whoever calls "add" will eventually
produce one warning log line in the common log file.
At the level of the "add" procedure I do not know anything
about log facility for which I'm to emit the log line i.e.
I do not know anything about the calling context.
Hence, this is very simple to use.
If I have 20 threads doing completely separate calculations
and I would like to isolate this log line for just a
bunch of them (i.e. ones within the "some context")
I could do:
ns_logctl register add_log whatever_id
The add_log procedure must now be clever enough to
"know" what to do for different "whatever_id" arguments.
In the above case, it might somehow obtain the current
value of the ID (whatever that is) in the current thread
and compare it with the passed argument.
So I'm *purposely* building the logic into the callback
and *not* into the server as this will be backward-compatible
for tons of existing code. And, it is much simpler to use
as I do not have to care about the calling context (or facility)
when writing ns_log lines. IOW, I can add the notion of the
"context" from the outside.
The main idea is: as simple as possible, backward-compatible
(no api changes to existing code), ability to route parts of
the global logs to separate log sinks for a "task" which is
potentially executed by number of threads. Every thread should
be able to isolate a "task" by calling some "gettaskid" procedure
which is entirely out of the scope of the log machinery, of course.
I'm sure that we can rewrite the log part to be much more
"fancy" but what we have now (ns_log) serves the purpose
very well and does not require me to think about the calling
context. The only drawback is the lack of finer granularity
as what goes where. I have tried to fill in that hole by
being mininally invasive on the API level.
Now, what do you think?
Cheers
Zoran
|
×
Want the latest updates on software, tech news, and AI?
Get latest updates about software, tech news, and AI from SourceForge directly in your inbox once a month.
Thanks for helping keep SourceForge clean.
X