Allow overriding twistd's logging options

[itamarst]

The use case of *adding* observers can be done simply by doing it in startService.

My suggestion is for replacing twistd's default - it checks for ILogging on
application. So, in the .tac we do:

from twisted.application.service import ILogging

class Logging:
    def initialize(self):
        log.startLoggingWithObserver(myObserver)

application.setComponent(ILogging, Logging())

[ralphm]

#1624 defers to here, but the comment by itamarst doesn't seem to be valid anymore. I see no reference of ILogger anywhere. Or is this a suggestion on how it could theoretically work and then used as shown?

[exarkun]

A suggestion about how it could work, I think.

[harshaw]

here are some patches to make this work.

[harshaw]

twistd patch

[harshaw]

twistd patch

[harshaw]

log.py patch (for the interface)

[harshaw]

disregard the second twistd.patch... sigh.

[therve]

I steel this, I've got a personal interest for this feature.

[itamarst]

.tac support is good, but twistd plugin support even more so. How are we going to do that? Presumably expand the plugin interface somehow.

[therve]

I tried something, that works for tac files, and also for plugins. It'd need lots of documentation, of course, but the real question is: how to test that?

[itamarst]

Comments:

1. ILogging could be better named. 2. The getLogFile method is redundant, it should just have getLogObserver. 3. getLogObserver shouldn't accept log file as argument; some observesrs will not use a file, e.g. syslog.

and there's the question of what happens when twistd options and the plugin/tac specify logging, which is probably the motivation for this version of ILogging.

[therve]

Replying to itamarst:

Comments: 1. ILogging could be better named.

Alright. Suggestions ? :)

2. The getLogFile method is redundant, it should just have getLogObserver.

I have a use case when I want to reuse default logfile. I want to customize both.

3. getLogObserver shouldn't accept log file as argument; some observesrs will not use a file, e.g. syslog.

syslog is not supported by this kind of customization.

and there's the question of what happens when twistd options and the plugin/tac specify logging, which is probably the motivation for this version of ILogging.

The only problem is when you want to use syslog, but it's stated as not supported, because I don't see how you could customize this. The file is specified in the options, and passed to getLogFile.

[itamarst]

Replying to therve:

1. ILogging could be better named.

Alright. Suggestions ? :)

ILoggerFactory or something.

2. The getLogFile method is redundant, it should just have getLogObserver.

I have a use case when I want to reuse default logfile. I want to customize both.

3. getLogObserver shouldn't accept log file as argument; some observesrs will not use a file, e.g. syslog.

syslog is not supported by this kind of customization.

Re-using twistd config is good, but the interface for doing so is not. "syslog is not supported by this kind of customization" doesn't make sense to me - why not?

seems to me your use-case is "pass twistd's logging options to the log observer factory, so it can override stuff." so:

def getLogObserver(logfile=None, syslog=False) will get called, with arguments based on whatever twistd options user provides. The implementation can choose to ignore one or both of these arguments. The default twistd behavior should be easily available to implementors so they can re-use it.

Obvious problem #1 with this proposal: what if we want to add more logging options to twistd?

[therve]

Replying to itamarst:

ILoggerFactory or something.

Looks good.

Re-using twistd config is good, but the interface for doing so is not. "syslog is not supported by this kind of customization" doesn't make sense to me - why not?

My main reason is because syslog seems to work well currently, with the existing options provided (and how can it be customized more ?). It doesn't bring nothing to use it in this system. The other reason is that I don't use syslog so I didn't care :). That's not a good reason though.

seems to me your use-case is "pass twistd's logging options to the log observer factory, so it can override stuff." so:

That's true.

def getLogObserver(logfile=None, syslog=False) will get called, with arguments based on whatever twistd options user provides. The implementation can choose to ignore one or both of these arguments. The default twistd behavior should be easily available to implementors so they can re-use it.

It seems fair. Although I still don't see the use case for syslog :).

Obvious problem 1 with this proposal: what if we want to add more logging options to twistd?

I'd say that we shouldn't, because if we bring this functionnality in tac/plugins, it's especially to not add another '--logclass=MySuperThing'. If the new system works good, there won't be more need for new options, as everything will be configurable with ILoggerFactory.

But the best way would be 'def getLogObserver(config, logfile=None)' ? This way we could add stuff into config without breaking anything.

Thanks a lot for your comments.

[itamarst]

(Adding Cory to the conversation, maybe he can help with NT Service info).

Replying to therve:

My main reason is because syslog seems to work well currently, with the existing options provided (and how can it be customized more ?). It doesn't bring nothing to use it in this system. The other reason is that I don't use syslog so I didn't care :). That's not a good reason though.

Perhaps one has a networked syslog implementation, but yes, it's not like most people will use it, but still...

I'd say that we shouldn't, because if we bring this functionnality in tac/plugins, it's especially to not add another '--logclass=MySuperThing'. If the new system works good, there won't be more need for new options, as everything will be configurable with ILoggerFactory.

Except that I can think of at least one logging system we will be adding sooner or later, Windows, when we finally get NT Service support going. Assuming I am remembering correctly and it's possible to use it for general logging, I might be wrong.

But the best way would be 'def getLogObserver(config, logfile=None)' ? This way we could add stuff into config without breaking anything.

If we pass config in there's probably no need for logfile, users can just do config["logfile"].

Even so, it seems like we still haven't really worked out a good way for twistd loging options to interoperate with plugin logging options. Here's an alternative proposal to think about: change getLogObserver to overrideLogObserver or some such, with config as argument. The developer can choose to call t.p.log.addLogObserver directly if they want. The method returns a boolean telling twistd whether or not it should add its own log observer. E.g.

def overrideLogObserver(config):
   twisted.python.log.addObserver(MyLogger(config["logfile"]).write)
   return True # suppress twistd's logging

Except... on Unix you might want to override, but perhaps on NT you'd want to add you logging in addition to NT Service log, and users shouldn't have to think about it. Maybe syslog option should be set to True on Windows for NT service thing and people can decide based on that, I dunno. Also you wouldn't be getting a logfile path on Windows. Anyone else have an idea?

Thanks a lot for your comments.

Thanks for working on this :)

[exarkun]

Replying to therve:

Replying to itamarst:

ILoggerFactory or something.

Looks good.

Re-using twistd config is good, but the interface for doing so is not. "syslog is not supported by this kind of customization" doesn't make sense to me - why not?

My main reason is because syslog seems to work well currently, with the existing options provided (and how can it be customized more ?). It doesn't bring nothing to use it in this system. The other reason is that I don't use syslog so I didn't care :). That's not a good reason though.

The advantage is reduction in code and complexity. Having two parallel systems which both do things to the logging system makes this area even hairier than it already is. Plus it introduces potential confusion to the user. What happens if you try to use the syslog options and provide an ILogger(/Factory?)? We should try to avoid the possibility for things like that.

seems to me your use-case is "pass twistd's logging options to the log observer factory, so it can override stuff." so:

That's true.

def getLogObserver(logfile=None, syslog=False) will get called, with arguments based on whatever twistd options user provides. The implementation can choose to ignore one or both of these arguments. The default twistd behavior should be easily available to implementors so they can re-use it.

It seems fair. Although I still don't see the use case for syslog :).

Obvious problem 1 with this proposal: what if we want to add more logging options to twistd?

I'd say that we shouldn't, because if we bring this functionnality in tac/plugins, it's especially to not add another '--logclass=MySuperThing'. If the new system works good, there won't be more need for new options, as everything will be configurable with ILoggerFactory. But the best way would be 'def getLogObserver(config, logfile=None)' ? This way we could add stuff into config without breaking anything.

Dictionaries of strings pretty much suck. :/ I think the case here is similar to the one trial's reporter plugins are dealing with. The existing logging options twistd offers are configuration for the existing log observer. They're not general logging options. Ideally, each logging plugin should be able to define and accept whatever options it wants, if we are going to allow options to be passed to logging plugins.

BTW, for anyone wondering, the code being discussed here is in improve-log-867

[exarkun]

Except not improve-log-867. Actually it's in twistd-logging-638.

[exarkun]

Some other comments now that I've actually looked at the code :)

• The docstring and whitespace cleanups in logfile.py and components.py should go in another branch, since they are actually the only changes in those files in this branch. It's fine to do cleanups near code that's changing anyway, but we should try to avoid going beyond that: it makes branches harder to review and makes looking back at changes which have been merged to trunk harder to understand.
• The changeLogging duplication between _twistw.py and _twistd_unix.py is pretty unfortunate. There should be some way to eliminate that.
• The only way to specify a custom log observer should not be via a custom subcommand! The application running is orthogonal to the log observer being used! Consider all of the existing twistd subcommands (web, words, conch, manhole, ftp, etc). We need to do something which is going to be usable with all of these.

[therve]

Replying to exarkun:

Some other comments now that I've actually looked at the code :) * The docstring and whitespace cleanups in logfile.py and components.py should go in another branch, since they are actually the only changes in those files in this branch. It's fine to do cleanups near code that's changing anyway, but we should try to avoid going beyond that: it makes branches harder to review and makes looking back at changes which have been merged to trunk harder to understand.

Agree. I've begin to make modifications to these files until I saw it wasn't necessary. I'll revert that.

* The changeLogging duplication between _twistw.py and _twistd_unix.py is pretty unfortunate. There should be some way to eliminate that.

The differences here are for syslog and daemon config. Apart that, much of the code is the same. ApplicationRunner should be a good place for this ?

* The only way to specify a custom log observer should not be via a custom subcommand! The application running is orthogonal to the log observer being used! Consider all of the existing twistd subcommands (web, words, conch, manhole, ftp, etc). We need to do something which is going to be usable with all of these.

Arg :). I knew the hack for plugins would be wrong somewhere. For this use case we need twistd options, because there's no user code. Here something like trial's reporters will be perfect I assume.

Side note: twistd seems untested, that's why I have such a pain to test this. Any pointers on how I could do this ?

[therve]

Replying to itamarst:

{{{ def overrideLogObserver(config): twisted.python.log.addObserver(MyLogger(configlogfile?).write) return True # suppress twistd's logging }}} Except... on Unix you might want to override, but perhaps on NT you'd want to add you logging in addition to NT Service log, and users shouldn't have to think about it. Maybe syslog option should be set to True on Windows for NT service thing and people can decide based on that, I dunno. Also you wouldn't be getting a logfile path on Windows. Anyone else have an idea?

That could be fine, but it's no very usable because the user has to do many things Twisted can do alone. Of course it's also more powerful, but we can already do that currently (I already do that in my application: remove the default log observer, and create a new one). But if I do that, I'll also have to handle SIGUSR1 rotate. I'll have to get the absolute path of the application to get full path to logfile. If we go like this the only thing we provide is a clean way to stop default logger.

What's my use case ? I want to customize the logFormat (for example, remove the date and just have H:M:S). So I need a custom LogObserver. And I want to customize how files are rotated (for example, daily), so I need a custom LogFile.

The need of something for subcommand goes in the same direction I think: the possibility to modify the LogObserver and the LogFile via twistd options.

[exarkun]

Replying to therve:

Replying to exarkun:

* The changeLogging duplication between _twistw.py and _twistd_unix.py is pretty unfortunate. There should be some way to eliminate that.

The differences here are for syslog and daemon config. Apart that, much of the code is the same. ApplicationRunner should be a good place for this ?

Yep, ApplicationRunner should be great.

* The only way to specify a custom log observer should not be via a custom subcommand! The application running is orthogonal to the log observer being used! Consider all of the existing twistd subcommands (web, words, conch, manhole, ftp, etc). We need to do something which is going to be usable with all of these.

Arg :). I knew the hack for plugins would be wrong somewhere. For this use case we need twistd options, because there's no user code. Here something like trial's reporters will be perfect I assume.

Oops, I guess I implied trial had already solved this problem :P But actually it suffers from exactly the same deficiency. What I meant to say was that both of these systems need a solution, and it's probably the same one. I'm not exactly sure what the best solution is yet, although I can think of a lot of kinda-okay solutions. For the sake of discussion, some of them are:

• Support a command line like twistd --logger=foo --logger-options='--bar baz' ...
• Support multiple subcommands somehow:
  • twistd logger --plugin foo web --path ...
  • twistd logger --plugin foo -- web --path ...

  • $ twistd commandline
    > logger --plugin foo
    > web --path ...
    > ^D
    

• Add config file support so logging options can be specified in a twistd.conf and don't need to be specified on the command line

But none of these really inspire me.

Side note: twistd seems untested, that's why I have such a pain to test this. Any pointers on how I could do this ?

Yea... Chris recently added the meager test coverage which does exist (twisted/test/test_twistd.py). Most twistd code predates the requirement for rigorous testing, which means it isn't factored to be easily testable at all. Do you think a test for the logging changes could fit into test_twistd.py? If not, I can try to take a harder look and see if I have any other ideas.

[therve]

Replying to exarkun:

* Add config file support so logging options can be specified in a twistd.conf and don't need to be specified on the command line

Yes, please. The twistd line is already looong, so if we need to add options I think it's a good mean. Furthermore, it will add configuration for all applications.

But it seems out of the scope of the ticket. Maybe we should add this feature before kicking logging ?

Side note: twistd seems untested, that's why I have such a pain to test this. Any pointers on how I could do this ?

Yea... Chris recently added the meager test coverage which does exist (twisted/test/test_twistd.py).

Thanks, I missed that one.

[exarkun]

Chris is great.

[itamarst]

We seem to have two use cases. To summarize:

1. Changing date format, log rotation policies, etc. on default twistd logging system. 2. Easy way to add and configure extra logging subsystems.

The current code is for #1, but seems too generalized in its current form; perhaps the interface should just expose settings/callback hooks for specific options related to default twistd logfiles. These would be less work for developers to implement, and the more general case would be served by #2.

For #2 UI is an issue. Perhaps the commandline plugin exarkun and I discussed would solve that problem (I will open a ticket soon, if exarkun does not). Perhaps we can leave #2 out of scope for this ticket.

[therve]

I've mixed harshaw's solution with mine, to have something that works with subcommands. I've added a sample plugin dailylogger, and some documentation to explain the functionality.

[exarkun]

I started to review this but I didn't get very far. Instead I wrote some more stuff on Specification/AdministrativeComponentSelection. I'll try to review this branch again soon, but if anyone wants to steal this ticket from me before I do it, please feel free.

[therve]

I've read the page you've setup. I'm a bit annoyed because you're concentrating on the part of the branch I don't care, around twistd command line options. I really think this is useless, because everything could be done inside the tac file. And most existing applications already have an external config file...

So if your point is that the options added is stupid, I'm not going to object: let's remove this. We could probably think about it later when we'll come with a good implementation in mind.

[glyph]

/over

[glyph]

The interface provided here, overrideLogObserver, has several problems.

• It invites abuse. Nothing prevents or discourages the user from manipulating non-logging-related options in the "config" object presented.
• It sets a precedent for other bad APIs. Are we going to have overrideUID? overrideSpewer? overrideReactor?
• It has no explicit channel for its own information. The documented example also encourages developers to change the meaning of existing logging options without providing any documentation or explanation of the fact that their plugin does this.

If we want plugins and tac files to be able to manipulate the options to twistd in a structured way, then twistd should first be converting its options into a structured object. I've filed a new ticket, #2571, for this task, which should be separated (and may in fact be broken down further).

[radix]

Here's what it should be:

application.setComponent(ILogObserver, o)

where 'o' implements the log observer interface; specifically, it is a callable of one dictionary argument.

[radix]

(In [24302]) Branching to 'configure-log-observer-638'

[radix]

ready for review

[itamar]

The branch doesn't document how I'd set logging in a twistd plugin, which one hopes will be more commonly used than .tac files... In particular, how do I get access to the all-important application object?

[radix]

Never mind, this sucks.

[therve]

I don't think we need the application object. Something like that in createOrGetApplication should do the trick:

if ILogObserver.providedBy(plg):
    application.setComponent(ILogObserver, plg)

[radix]

Alright, how about now?

[exarkun]

(In [24422]) Branching to 'configure-log-observer-638-2'

[exarkun]

• twisted/python/log.py
  • update copyright date
  • ILogObserver.__call__ incorrectly includes self in the parameter list
  • In the list of often available keys, the keys should probably be strings, yes?

I think there could be better user-facing behavior if a name supplied to --logger doesn't actually give a valid FQPN. Might also be worth mentioning --logger also overrides --syslog?

[exarkun]

Note, a large portion of the changes in this branch were moved into a branch for a different ticket, #3534.

[exarkun]

#4676 was a duplicate of this.

[itamarst]

(In [31793]) Branching to 'configure-log-observer-638-3'

[itamar]

I addressed the review comments that were still relevant (better behavior for unimportable --logger), added tests that --logger overrides --logfile and --syslog, and cleaned things up a bit.

Test results were *supposed* to be here --  http://buildbot.twistedmatrix.com/boxes-supported?branch=/branches/configure-log-observer-3 -- but bzr is having issues or something.

[exarkun]

Here -  http://buildbot.twistedmatrix.com/boxes-supported?branch=/branches/configure-log-observer-638-3 (note extra number :)

[thijs]

• doc/core/man/twistd.1 has a copyright date that needs to be updated (or removed)
• the modified docstring in AppLogger.start contains --logfile that should be wrapped in C{}`
• the UsageError there can be documented using @raise UsageError: ...

[thijs]

Also see #3513 that depends on this ticket.

[itamar]

Review comments have been addressed.

[itamar]

Urgh. Put it up for review again.

[therve]

1.

+                observerFactory = namedAny(self._observerFactoryName)
+            except ObjectNotFound, e:
+                raise usage.UsageError("Logger '%s' could not be imported." % (
+                        self._observerFactoryName,))

ObjectNotFound is only one of the errors that namedAny can raise. It would be nice to catch at least ModuleNotFound and AttributeError as well.

2;

+def _setupSyslog(testCase):
+    """
+    Make fake syslog, and return list to which prefix and then log
+    messages will be appended if it is used.
+    """
+    L = []

Please use a better variable name than L.

3.

+        try:
+            logger.start(application)
+        finally:
+            sys.modules.pop("__twisted_test_log_observer", None)

Please use addCleanup instead.

4. You should use assertEqual instead of assertEquals.

5.

+        self.assertTrue(not os.path.exists(path))

Please use assertFalse.

Those are relatively trivial, but there are 5 points, so I'd like to have another look. Thanks!

[itamarst]

(In [32168]) Address review comments. Refs #638

[itamar]

Back to review.

[exarkun]

Yay, logging, and stuff :/ Thanks for taking one for the team.

The biggest shortcoming of the branch appears to be that it still ignores the issue of configuring log observers. No one cares about this I guess? Including the fact that it's not even possible to set up an equivalent to the default log observer using this option?

1. The namedAny call is in the wrong place. Put it in postOptions or in a coercer for the logger option. Then you can undo the change in app.py to put the runApp call inside the try/except usage.error block (where it doesn't belong at all).
2. Rather than using a hopefully-unique name like "twisted_test_log_observer" in _setupConfiguredLogger, how about something the test can guarantee is unique, by starting the name with "twisted.test.test_twistd." and adding some unique suffix?
3. Trivial conflict in the twistd man page
4. Some new pyflakes warnings in test_twistd.py and app.py

 Latest build results, fwiw.

[exarkun]

Hey, there's another reason not to use names like __twisted_test_log_observer.

[itamar]

"The biggest shortcoming of the branch appears to be that it still ignores the issue of configuring log observers. No one cares about this I guess?" I.e., how does one determine what options the custom log observer gets?

I could add a --logger-options command line argument, though I'm not quite sure how to do multiple arguments; maybe one is sufficient, or allow multiple --logger-options. Since I want to replace .tac files with "twistd run", I'm willing to do the work to get the logger override code in good enough shape to replace the logging functionality .tacs provide.

[itamar]

OK, my proposal re options: open a new ticket for extending --logger, with a new optional format "--logger=fqdn:opt1=foo,opt2=bar", basically the same way string services work. That way this branch will both be small and commitable, and future compatible.

[exarkun]

string endpoint descriptions don't use fqdn though, they use a plugin identified by the first part of the string which provide a parser for the rest of it.

[itamar]

The bit after the colon would be like endpoint descriptions, is what I meant.

[itamarst]

(In [32224]) Branching to 'configure-log-observer-638-4'

[itamarst]

(In [32226]) Address review comments. Refs #638

[itamar]

I've addressed review comments, except that I don't see new pyflakes warnings in test_twisted. Test run here:

 http://buildbot.twistedmatrix.com/boxes-supported?branch=/branches/configure-log-observer-638-4

Question to reviewer: should this ticket including option passing to --logger, or is that new ticket?

[exarkun]

1. There's a conflict in twisted/test/test_twistd.py
2. The change to twisted.application.app.run is wrong (and sadly causes no test failures)
3. The twistd documentation should be updated to cover this new feature.
4. Let's get this ticket behind us. Additional configuration for the --logger isn't going to change the basic interface or functionality. Or will it? --logger is specifying an ILogObserver provider; that interface has no support for configuration, so how will the object be given the configuration specified by a user?

If you can answer the last question without changing this branch much, and if you merge forward and get a green build on buildbot, then go ahead and merge. Otherwise please resubmit for review with the changes. Thanks.

[exarkun]

Uh. Let me amend that now that my brain is working a little better.

3. The doc changes to application.xhtml, logging.xhtml, and twistd.1 look good.
4. The configuration feature can be separate, since it presumably will just be the addition of a way to pass arguments to the log observer factory callable specified by --logger.

Please merge forward and test on buildbot, and merge if the result is green. Thanks.

[itamarst]

(In [32387]) Branching to 'configure-log-observer-638-5'

[itamarst]

(In [32391]) Merge configure-log-observer-638-5: --logger command-line for twistd.

Author: radix, itamar Reviewer: therve, thijs, exarkun Fixes: #638

Add a --logger command-line to twistd that allows specifying a custom log observer.

[exarkun]

You forgot to address the 2nd point from comment 68. Now the behavior for incorrect usage is:

./bin/twistd: Logger 'aslkdjaklsjd' could not be imported: No module named 'aslkdjaklsjd'
Unhandled Error
Traceback (most recent call last):
  File "/home/exarkun/Projects/Twisted/trunk/twisted/application/app.py", line 640, in run
    runApp(config)
  File "/home/exarkun/Projects/Twisted/trunk/twisted/scripts/twistd.py", line 23, in runApp
    _SomeApplicationRunner(config).run()
  File "/home/exarkun/Projects/Twisted/trunk/twisted/application/app.py", line 385, in run
    self.application = self.createOrGetApplication()
  File "/home/exarkun/Projects/Twisted/trunk/twisted/application/app.py", line 450, in createOrGetApplication
    application = getApplication(self.config, passphrase)
--- <exception caught here> ---
  File "/home/exarkun/Projects/Twisted/trunk/twisted/application/app.py", line 461, in getApplication
    application = service.loadApplication(filename, style, passphrase)
  File "/home/exarkun/Projects/Twisted/trunk/twisted/application/service.py", line 402, in loadApplication
    application = sob.load(filename, kind, passphrase)
  File "/home/exarkun/Projects/Twisted/trunk/twisted/persisted/sob.py", line 170, in load
    fp = open(filename, mode)
exceptions.IOError: [Errno 2] No such file or directory: 'twistd.tap'

Failed to load application: [Errno 2] No such file or directory: 'twistd.tap'

[itamar]

Oh, sorry, I thought the amended version replaced all of the items in the previous comment. Now to figure out how to revert...

[itamarst]

(In [32394]) Revert fix for #638.

Reopens: #638

[itamarst]

(In [32397]) Merge configure-log-observer-638-5: --logger command-line for twistd.

Author: radix, itamar Reviewer: therve, thijs, exarkun Fixes: #638

Add a --logger command-line to twistd that allows specifying a custom log observer.