apiserver/logger: adding command for debug log

apiserver/logger: adding command for debug log

The command providing a filtered watching of the all-machines.log
is handled by the new component logTailer based on the Tailer.

N.B. While the logTailer and the here used channelWriter are
     already tested the tests for the API itself are still missing.
     This finishing will be pushed extra in the same CL.

N.B. The CL also contains a small detected fix for the Tailer.

https://code.launchpad.net/~themue/juju-core/058-debug-log-api/+merge/199799

(do not edit description out of merge proposal)

[mue, 2013-12-20 12:48:03]

Please take a look.

[fwereade, 2014-01-02 09:35:08]

Mostly solid, but I have a few significant concerns. Let me know your thoughts.

https://codereview.appspot.com/44540043/diff/1/state/api/logger/logger.go
File state/api/logger/logger.go (right):

https://codereview.appspot.com/44540043/diff/1/state/api/logger/logger.go#new...
state/api/logger/logger.go:73: // WatchDebugLog starts a StringsWatcher to watch
the all machines log. The initial
This is definitely the wrong place for this code. This package is (while
admittedly badly named) for the use of agents looking up their logging config.
The WatchDebugLog functionality is only relevant to clients -- and so it should
either be in api/client (kinda bad, because that's hideously bloated already) or
in some new package (maybe tricky to name properly, but probably worth the
effort).

https://codereview.appspot.com/44540043/diff/1/state/api/logger/logger.go#new...
state/api/logger/logger.go:78: Watchings: []params.DebugLogWatching{
I don't think "Watchings" means anything. "Entities"?

And FWIW I think that an empty tag is an error. If you want all the
environment's logs, ask for them explicitly ;).

https://codereview.appspot.com/44540043/diff/1/state/api/params/internal.go
File state/api/params/internal.go (right):

https://codereview.appspot.com/44540043/diff/1/state/api/params/internal.go#n...
state/api/params/internal.go:25: }
This shouldn't be in internal.go, shouldit? I thought this was a client API?

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logger.go
File state/apiserver/logger/logger.go (right):

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logger....
state/apiserver/logger/logger.go:122: defer logTailer.Stop()
Huh? Why are we stopping it as soon as it's started?

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
File state/apiserver/logger/logtailer.go (right):

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:27: func startLogTailer(filename string,
lines int, tag string) (*logTailer, error) {
"tag" is used at the wrong level here, I think: AFAICT this is the only thing in
this file that knows about juju-level concepts like "tags", or makes inferences
about the precise format of the logs. Shouldn't it be a `prefix string` param?

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:29: var filter tailer.TailerFilterFunc
please fix stuttering

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:55: return lt.writer.Changes()
I found this really confusing at first glance -- can we call the writer's method
something other than "Changes" please? I think the place for pretending to be a
watcher is in this "tailer" type, not the underlying "writer" type.

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:62: defer lt.logFile.Close()
I think we need to keep track of these errors, don't we?

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:95: cw.in <- p
Select on cw.tomb.Dying please, otherwise this method will block forever if the
writer's stopped at a bad time.

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:113: send := func() {
It might be nice to move the repeated "if lines != nil" inside this func.

And possibly better to call it "trySend" or something to make explicit the fact
that it's not expected to actually send anything?

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:123: return nil
tomb.ErrDying

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:138: }
I think the high-level behaviour is a bit problematic -- if a client ever fails
to call Next(), lines will grow without bound until it disconnects, and if this
is a whole-environment watcher in debug mode that could be quite a lot of data.
How can we prevent a mischievous client from starting one of these, abandoning
it, and just waiting for it to take down the API server?

[mue, 2014-01-09 13:07:58]

Please take a look.

https://codereview.appspot.com/44540043/diff/1/state/api/logger/logger.go
File state/api/logger/logger.go (right):

https://codereview.appspot.com/44540043/diff/1/state/api/logger/logger.go#new...
state/api/logger/logger.go:73: // WatchDebugLog starts a StringsWatcher to watch
the all machines log. The initial
On 2014/01/02 09:35:09, fwereade wrote:
> This is definitely the wrong place for this code. This package is (while
> admittedly badly named) for the use of agents looking up their logging config.
> The WatchDebugLog functionality is only relevant to clients -- and so it
should
> either be in api/client (kinda bad, because that's hideously bloated already)
or
> in some new package (maybe tricky to name properly, but probably worth the
> effort).

Oh, didn't recognized this meaning of the logger package. Created a new one,
first naming approach is "debugger". Right now only the log watching, but maybe
later more helpful environment debugging functions.

https://codereview.appspot.com/44540043/diff/1/state/api/logger/logger.go#new...
state/api/logger/logger.go:78: Watchings: []params.DebugLogWatching{
On 2014/01/02 09:35:09, fwereade wrote:
> I don't think "Watchings" means anything. "Entities"?
> 
> And FWIW I think that an empty tag is an error. If you want all the
> environment's logs, ask for them explicitly ;).

Renaming is ok, will be done. But today passing no tag means simply tailing the
whole debug log, without filtering. So without this possibility we would change
the behaviour of the command or would have to add another argument (all bool).

https://codereview.appspot.com/44540043/diff/1/state/api/params/internal.go
File state/api/params/internal.go (right):

https://codereview.appspot.com/44540043/diff/1/state/api/params/internal.go#n...
state/api/params/internal.go:25: }
On 2014/01/02 09:35:09, fwereade wrote:
> This shouldn't be in internal.go, shouldit? I thought this was a client API?

(facepalm) Didn't really recognized the idea behind the special file name while
all share the same package.

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logger.go
File state/apiserver/logger/logger.go (right):

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logger....
state/apiserver/logger/logger.go:122: defer logTailer.Stop()
On 2014/01/02 09:35:09, fwereade wrote:
> Huh? Why are we stopping it as soon as it's started?

(argh) Reflex.

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
File state/apiserver/logger/logtailer.go (right):

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:27: func startLogTailer(filename string,
lines int, tag string) (*logTailer, error) {
On 2014/01/02 09:35:09, fwereade wrote:
> "tag" is used at the wrong level here, I think: AFAICT this is the only thing
in
> this file that knows about juju-level concepts like "tags", or makes
inferences
> about the precise format of the logs. Shouldn't it be a `prefix string` param?

Done so, and it's ok as long as we write the entity tag as prefix. In case we
change the log format to start with the timestamp as usual and containing the
tag like it today contains the class (info, error, debug) it is more than a
prefix.

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:29: var filter tailer.TailerFilterFunc
On 2014/01/02 09:35:09, fwereade wrote:
> please fix stuttering

Huh?

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:55: return lt.writer.Changes()
On 2014/01/02 09:35:09, fwereade wrote:
> I found this really confusing at first glance -- can we call the writer's
method
> something other than "Changes" please? I think the place for pretending to be
a
> watcher is in this "tailer" type, not the underlying "writer" type.

Done.

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:62: defer lt.logFile.Close()
On 2014/01/02 09:35:09, fwereade wrote:
> I think we need to keep track of these errors, don't we?

Added logging, don't think that nested error messages would help more.

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:95: cw.in <- p
On 2014/01/02 09:35:09, fwereade wrote:
> Select on cw.tomb.Dying please, otherwise this method will block forever if
the
> writer's stopped at a bad time.

Done.

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:113: send := func() {
On 2014/01/02 09:35:09, fwereade wrote:
> It might be nice to move the repeated "if lines != nil" inside this func.
> 
> And possibly better to call it "trySend" or something to make explicit the
fact
> that it's not expected to actually send anything?

Done.

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:123: return nil
On 2014/01/02 09:35:09, fwereade wrote:
> tomb.ErrDying

Done.

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:138: }
On 2014/01/02 09:35:09, fwereade wrote:
> I think the high-level behaviour is a bit problematic -- if a client ever
fails
> to call Next(), lines will grow without bound until it disconnects, and if
this
> is a whole-environment watcher in debug mode that could be quite a lot of
data.
> How can we prevent a mischievous client from starting one of these, abandoning
> it, and just waiting for it to take down the API server?

Added the possibility to pass a maximum number of lines to keep and tested it.
No real integration in the API so far, only a constant. Another idea would be to
truncate time based.

[mue, 2014-01-10 11:34:40]

Please take a look.

[mue, 2014-01-10 12:33:01]

Please take a look.

[william.reade, 2014-01-13 09:31:01]

preliminary responses pre-full-review

https://codereview.appspot.com/44540043/diff/1/state/api/logger/logger.go
File state/api/logger/logger.go (right):

https://codereview.appspot.com/44540043/diff/1/state/api/logger/logger.go#new...
state/api/logger/logger.go:78: Watchings: []params.DebugLogWatching{
On 2014/01/09 13:07:59, mue wrote:
> On 2014/01/02 09:35:09, fwereade wrote:
> > I don't think "Watchings" means anything. "Entities"?
> > 
> > And FWIW I think that an empty tag is an error. If you want all the
> > environment's logs, ask for them explicitly ;).
> 
> Renaming is ok, will be done. But today passing no tag means simply tailing
the
> whole debug log, without filtering. So without this possibility we would
change
> the behaviour of the command or would have to add another argument (all bool).

We shouldn't change the command, true; but we're trying to design a helpful API,
and when we're asking for a whole environment's logs it seems smartest to
request them with the environment tag, just as we request a unit's logs with the
unit tag or a machine's logs with the machine tag.

Is there some other set of logs that better answers the description "logs for
the environment"?

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
File state/apiserver/logger/logtailer.go (right):

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:29: var filter tailer.TailerFilterFunc
On 2014/01/09 13:07:59, mue wrote:
> On 2014/01/02 09:35:09, fwereade wrote:
> > please fix stuttering
> 
> Huh?

"tailer.TailerFilterFunc" is a bit icky compared to "tailer.FilterFunc"

https://codereview.appspot.com/44540043/diff/1/state/apiserver/logger/logtail...
state/apiserver/logger/logtailer.go:138: }
On 2014/01/09 13:07:59, mue wrote:
> On 2014/01/02 09:35:09, fwereade wrote:
> > I think the high-level behaviour is a bit problematic -- if a client ever
> fails
> > to call Next(), lines will grow without bound until it disconnects, and if
> this
> > is a whole-environment watcher in debug mode that could be quite a lot of
> data.
> > How can we prevent a mischievous client from starting one of these,
abandoning
> > it, and just waiting for it to take down the API server?
> 
> Added the possibility to pass a maximum number of lines to keep and tested it.
> No real integration in the API so far, only a constant. Another idea would be
to
> truncate time based.

Yeah, I'd been thinking of a time-based one myself. Would surely be rather
similar to the client disconnect logic you did a few weeks ago -- anything we
can reuse, perhaps?

[william.reade, 2014-01-14 14:41:41]

Nearly there, I think.

https://codereview.appspot.com/44540043/diff/60001/state/api/logger/logger.go
File state/api/logger/logger.go (right):

https://codereview.appspot.com/44540043/diff/60001/state/api/logger/logger.go...
state/api/logger/logger.go:75: func (st *State) WatchDebugLog(lines int, tag
string) (watcher.StringsWatcher, error) {
This is still on the wrong facade, isn't it?

https://codereview.appspot.com/44540043/diff/60001/state/api/params/params.go
File state/api/params/params.go (right):

https://codereview.appspot.com/44540043/diff/60001/state/api/params/params.go...
state/api/params/params.go:48: type DebugLogWatching struct {
Still not keen on the noun "Watching". If anything it's an EntityLogRequest or
something -- and DebugLogWatchings.Watchings should be .Entities -- I think.

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/d...
File state/apiserver/debugger/debugger.go (right):

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/d...
state/apiserver/debugger/debugger.go:63: // one machine or unit.
or environment.

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/d...
state/apiserver/debugger/debugger.go:66: logTailer, err :=
startLogTailer(logLocation, arg.Lines, 5, arg.Tag)
yeah, the handling of arg.Tag should happen here. I think it probably makes most
sense to construct a FilterFunc here and pass it in -- that keeps the
API-specific stuff at the API level and takes a responsibility off the tailer's
plate.

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/l...
File state/apiserver/debugger/logtailer.go (right):

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/l...
state/apiserver/debugger/logtailer.go:40: }
I still kinda feel this shouldn't know about tags. The client is surely in a
position to parse tags (ie check validity in a juju context) and append ":" (or
": " maybe?), and then pass a literal prefix, devoid of meaning, into
startLogTailer -- or even a straight tailer.FilterFunc.

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/l...
state/apiserver/debugger/logtailer.go:48: // number of initial lines, otherwise
those would be trunkated.
s/trunkated/truncated/

[mue, 2014-01-15 13:14:16]

Please take a look.

https://codereview.appspot.com/44540043/diff/60001/state/api/logger/logger.go
File state/api/logger/logger.go (right):

https://codereview.appspot.com/44540043/diff/60001/state/api/logger/logger.go...
state/api/logger/logger.go:75: func (st *State) WatchDebugLog(lines int, tag
string) (watcher.StringsWatcher, error) {
On 2014/01/14 14:41:41, william.reade wrote:
> This is still on the wrong facade, isn't it?

Yep, recognized it too. Is already moved, you'll see it with the next push.

https://codereview.appspot.com/44540043/diff/60001/state/api/params/params.go
File state/api/params/params.go (right):

https://codereview.appspot.com/44540043/diff/60001/state/api/params/params.go...
state/api/params/params.go:48: type DebugLogWatching struct {
On 2014/01/14 14:41:41, william.reade wrote:
> Still not keen on the noun "Watching". If anything it's an EntityLogRequest or
> something -- and DebugLogWatchings.Watchings should be .Entities -- I think. 

Sounds reasonable.

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/d...
File state/apiserver/debugger/debugger.go (right):

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/d...
state/apiserver/debugger/debugger.go:63: // one machine or unit.
On 2014/01/14 14:41:41, william.reade wrote:
> or environment.

Done.

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/d...
state/apiserver/debugger/debugger.go:66: logTailer, err :=
startLogTailer(logLocation, arg.Lines, 5, arg.Tag)
On 2014/01/14 14:41:41, william.reade wrote:
> yeah, the handling of arg.Tag should happen here. I think it probably makes
most
> sense to construct a FilterFunc here and pass it in -- that keeps the
> API-specific stuff at the API level and takes a responsibility off the
tailer's
> plate.

Had a very similar change implemented, yep. Only needed few changes to do it
this way.

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/l...
File state/apiserver/debugger/logtailer.go (right):

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/l...
state/apiserver/debugger/logtailer.go:40: }
On 2014/01/14 14:41:41, william.reade wrote:
> I still kinda feel this shouldn't know about tags. The client is surely in a
> position to parse tags (ie check validity in a juju context) and append ":"
(or
> ": " maybe?), and then pass a literal prefix, devoid of meaning, into
> startLogTailer -- or even a straight tailer.FilterFunc.

Removed ParseTag() (but left colon adding) and moved it.

https://codereview.appspot.com/44540043/diff/60001/state/apiserver/debugger/l...
state/apiserver/debugger/logtailer.go:48: // number of initial lines, otherwise
those would be trunkated.
On 2014/01/14 14:41:41, william.reade wrote:
> s/trunkated/truncated/

Iiirks, thanks. ;)

[mue, 2014-01-17 13:23:42]

Please take a look.

[mue, 2014-01-17 17:12:48]

Please take a look.

[mue, 2014-01-21 08:48:47]

Please take a look.

[mue, 2014-01-21 16:03:09]

Please take a look.

[mue, 2014-01-23 14:16:54]

Please take a look.

[fwereade, 2014-01-23 16:22:58]

Looking good, but I think we need to know a bit more about how it handles load.
Dropping lines seems *really* bad, but erroring out without reasonably extreme
provocation is also bad.

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
File state/apiserver/debugger/debugger.go (right):

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
state/apiserver/debugger/debugger.go:25: const maxLogLines = 256
How long does it take for this to be filled in a moderately busy environment?
Say 20 units, all running hooks? I think this number should probably be quite a
lot larger...

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
state/apiserver/debugger/debugger.go:78: if entity.Tag != environ.Tag() {
I think we should filter out tags that aren't machine/unit ones. It's fine if
they don't exist, I think (historical information feels to me like it could be
valid), but not fine if they're not well-formed or for sensible entities.

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
state/apiserver/debugger/debugger.go:90: if changes, ok :=
<-logTailer.Changes(); ok {
Is this guaranteed to return an empty []string if there aren't any to send yet?
The expectation for stringswatchers is that the initial request will return
soon.

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
File state/apiserver/debugger/debugger_test.go (right):

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
state/apiserver/debugger/debugger_test.go:68: initialCollected: []string{},
looks like it is, nice :)

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
File state/apiserver/debugger/logtailer.go (right):

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
state/apiserver/debugger/logtailer.go:193: lines =
lines[len(lines)-cw.maxLines:]
I don't think this is correct -- silently skipping changes STM to be far worse
than straight-up failing.

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/root.go
File state/apiserver/root.go (right):

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/root.go#n...
state/apiserver/root.go:165: func (r *srvRoot) Debugger(id string)
(*debugger.DebuggerAPI, error) {
This should probably be requiring a client, right?

[mue, 2014-01-23 16:41:51]

Thank you for your hints, will change the code.

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
File state/apiserver/debugger/debugger.go (right):

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
state/apiserver/debugger/debugger.go:25: const maxLogLines = 256
On 2014/01/23 16:22:58, fwereade wrote:
> How long does it take for this to be filled in a moderately busy environment?
> Say 20 units, all running hooks? I think this number should probably be quite
a
> lot larger...

Yeah, no problem, has been a first shot. 2^16 too high? Funnily still using
binary numbers, but also could be 10 000, 50 000 or 100 000.

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
state/apiserver/debugger/debugger.go:78: if entity.Tag != environ.Tag() {
On 2014/01/23 16:22:58, fwereade wrote:
> I think we should filter out tags that aren't machine/unit ones. It's fine if
> they don't exist, I think (historical information feels to me like it could be
> valid), but not fine if they're not well-formed or for sensible entities.

Would reduce the amount of data too, good. But in case of the environment tag
still everything?

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
state/apiserver/debugger/debugger.go:90: if changes, ok :=
<-logTailer.Changes(); ok {
On 2014/01/23 16:22:58, fwereade wrote:
> Is this guaranteed to return an empty []string if there aren't any to send
yet?
> The expectation for stringswatchers is that the initial request will return
> soon.

See tests. Also testing on EC2 showed a fine behavior. :)

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
File state/apiserver/debugger/debugger_test.go (right):

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
state/apiserver/debugger/debugger_test.go:68: initialCollected: []string{},
On 2014/01/23 16:22:58, fwereade wrote:
> looks like it is, nice :)

\o/

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
File state/apiserver/debugger/logtailer.go (right):

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/debugger/...
state/apiserver/debugger/logtailer.go:193: lines =
lines[len(lines)-cw.maxLines:]
On 2014/01/23 16:22:58, fwereade wrote:
> I don't think this is correct -- silently skipping changes STM to be far worse
> than straight-up failing.

So if the (increased) limit is reached return with an error? Would be at least a
well defined behavior, yes. Will change.

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/root.go
File state/apiserver/root.go (right):

https://codereview.appspot.com/44540043/diff/180001/state/apiserver/root.go#n...
state/apiserver/root.go:165: func (r *srvRoot) Debugger(id string)
(*debugger.DebuggerAPI, error) {
On 2014/01/23 16:22:58, fwereade wrote:
> This should probably be requiring a client, right?

See api/client.go line 533ff. But maybe I'm getting the mechanisms of the API
wrong. I also would have preferred a different package structure:

juju-core/api
        .../common
        .../client
        .../server
juju-core/state

Sometimes I've been lost in the dependencies and namings.