twisted names is too chatty while resolving names

[bra]

Even resolving a single name is just a little bit overkill, from the logging point of view (not to speak about the usability of these), but when doing a lot of resolutions, it affects performance and the health of the user, too:

2009-09-14 15:11:55+0200 [-] Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x28e4ce6c>
2009-09-14 15:11:55+0200 [-] (Port 58178 Closed)
2009-09-14 15:11:55+0200 [-] Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x28e4ce6c>
2009-09-14 15:11:55+0200 [-] <class 'twisted.names.dns.DNSDatagramProtocol'> starting on 51219
2009-09-14 15:11:55+0200 [-] Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x28e4ce6c>
2009-09-14 15:11:55+0200 [-] (Port 51219 Closed)
2009-09-14 15:11:55+0200 [-] Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x28e4ce6c>
2009-09-14 15:11:55+0200 [-] <class 'twisted.names.dns.DNSDatagramProtocol'> starting on 41031
2009-09-14 15:11:55+0200 [-] Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x28e4cc6c>
2009-09-14 15:11:55+0200 [-] (Port 41031 Closed)
2009-09-14 15:11:55+0200 [-] Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x28e4cc6c>
2009-09-14 15:11:55+0200 [-] <class 'twisted.names.dns.DNSDatagramProtocol'> starting on 19802
2009-09-14 15:11:55+0200 [-] Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x28e4cc6c>
2009-09-14 15:11:55+0200 [-] (Port 19802 Closed)
2009-09-14 15:11:55+0200 [-] Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x28e4cc6c>
2009-09-14 15:11:55+0200 [-] <class 'twisted.names.dns.DNSDatagramProtocol'> starting on 15653
2009-09-14 15:11:55+0200 [-] Starting protocol <twisted.names.dns.DNSDatagramProtocol object at 0x28e4ce6c>
2009-09-14 15:11:55+0200 [-] (Port 15653 Closed)
2009-09-14 15:11:55+0200 [-] Stopping protocol <twisted.names.dns.DNSDatagramProtocol object at 0x28e4ce6c>

Therefore I propose to lower "noisy" levels and check that variable in protocols too.

Patch attached.

[bra]

proposed patch, making twisted protocols less chatty by default

[exarkun]

Thanks. The logging going on here is indeed somewhat excessive. I don't think this applies to all of Twisted Names, though - are you doing the lookup on Windows, or by explicitly selecting the root resolver? I wouldn't expect this much noise otherwise.

As for the patch, I think that changing the defaults for all of Twisted is perhaps an overly broad change to address this issue. I think some discussion about changes to that part of Twisted would be welcome, but you should bring it up on the mailing list (or dig up some of the old discussions that no one ever acted on). To fix this particular issue, wouldn't a more direct solution be to set noisy to False just on the DatagramProtocol instances being created by the resolver?

Also, we try to encourage test-driven development and aim for full line coverage. Can you include some unit tests in the next version of the patch? If it's not clear how to test this change, I can try to give you some pointers.

[exarkun]

Ah, one other thing. When you want someone with commit access to look at a ticket and consider applying a patch attached to it, please add the "review" keyword to the ticket.

[bra]

Replying to exarkun:

Thanks. The logging going on here is indeed somewhat excessive. I don't think this applies to all of Twisted Names, though - are you doing the lookup on Windows, or by explicitly selecting the root resolver? I wouldn't expect this much noise otherwise.

What I'm trying to achieve here with twisted is to monitor multiple servers' response rate and time. On unix(-like, FreeBSD). I have a pool of servers in a list:

r.append(client.Resolver(servers=[srv],timeout=[timeout]))

then I query all of them with (res is one element of the above list):

res.lookupAddress(qryname).addCallback(gotAddress,serverip,qrystart,type).addErrback(gotError,serverip,qrystart,type)

BTW, there is another problem, which I think comes from the fact that the code, invoked as above is not a general resolver, but a specific one, which wants to be smart. :) The problem is that when you ask the same name many times and one of them fails (a timeout for example), all pending queries will fail, regardless they are served by the server. I don't know whether this qualify an error or not, it depends on the purpose of the library. But it would be nice to have "full control" or at least not to fool the user with false errors when there are. What do you think about that? I couldn't look at the code in depth, so I don't know how hard would be to correct only this one.

As for the patch, I think that changing the defaults for all of Twisted is perhaps an overly broad change to address this issue. I think some discussion about changes to that part of Twisted would be welcome, but you should bring it up on the mailing list (or dig up some of the old discussions that no one ever acted on). To fix this particular issue, wouldn't a more direct solution be to set noisy to False just on the DatagramProtocol instances being created by the resolver?

You may be right, but the patch also has ifs. Currently you can't turn these messages off by setting noisy to False, because those printouts don't check that. And these are not error conditions, just internals of the code...

Also, we try to encourage test-driven development and aim for full line coverage. Can you include some unit tests in the next version of the patch? If it's not clear how to test this change, I can try to give you some pointers.

It would be welcome, thanks. I'm not sure what (and how) could be tested on some overly chatty log.msgs. :)

Thanks for the quick response!

[exarkun]

The problem is that when you ask the same name many times and one of them fails (a timeout for example), all pending queries will fail, regardless they are served by the server. I don't know whether this qualify an error or not, it depends on the purpose of the library. But it would be nice to have "full control" or at least not to fool the user with false errors when there are. What do you think about that?

To get this kind of full control, you probably just want to switch to a slightly lower-level API. I think that you can get the behavior you desire if you use twisted.names.dns.DNSDatagramProtocol directly. It has a query method as well, and it doesn't implement the birthday-attack protection that's causing the behavior you're describing.

You may be right, but the patch also has ifs. Currently you can't turn these messages off by setting noisy to False, because those printouts don't check that. And these are not error conditions, just internals of the code...

Yea, and this is one of the points discussed on the mailing list in the past, I think. Throwing in more and more if statements around logging isn't a great solution. The noisy attribute was introduced in, oh, 2002 or so. It was a hack, and we shouldn't expand on it. A better solution would involve making the log messages structured and allowing the observer to ignore them if it wants.

[bra]

Replying to exarkun:

The problem is that when you ask the same name many times and one of them fails (a timeout for example), all pending queries will fail, regardless they are served by the server. I don't know whether this qualify an error or not, it depends on the purpose of the library. But it would be nice to have "full control" or at least not to fool the user with false errors when there are. What do you think about that?

To get this kind of full control, you probably just want to switch to a slightly lower-level API. I think that you can get the behavior you desire if you use twisted.names.dns.DNSDatagramProtocol directly. It has a query method as well, and it doesn't implement the birthday-attack protection that's causing the behavior you're describing.

You may be right, but the patch also has ifs. Currently you can't turn these messages off by setting noisy to False, because those printouts don't check that. And these are not error conditions, just internals of the code...

Yea, and this is one of the points discussed on the mailing list in the past, I think. Throwing in more and more if statements around logging isn't a great solution. The noisy attribute was introduced in, oh, 2002 or so. It was a hack, and we shouldn't expand on it. A better solution would involve making the log messages structured and allowing the observer to ignore them if it wants.

Hmm, I see, and I agree, but this extra verbosity is not great, nevertheless.

BTW, how hard would it be to provide a hierarchical logging facility, with the ability to set the needed loglevel for each caller (eg. twisted.names.dns must be at least at info, etc) and log only what's above that? And log.msg without a level set would be -say- at info.

[exarkun]

It's more a question of desirability than difficulty. See #307.

[jasonjwwilliams]

Looks like there hasn't been any work on this in awhile. I'm having issues with the chattiness of the Twisted Name client filling up the logs with the start/stop messages. Besides filling the disk needlessly, it makes it hard to find an important log message in a see of DNS start/stops.

It looks like _bindSocket() in Port (twisted/internet/udp.py) is where it has to be taken care of (as done in the above patch). Was the objection to the patch the wrapping of the log statement in an if (to detect noisy) or the change of noisy's default from True to False? If the latter, I'd be happy to put together another patch with tests to enable this to use the self.noisy from the class.

[exarkun]

Was the objection to the patch the wrapping of the log statement in an if (to detect noisy) or the change of noisy's default from True to False?

Both, neither, who knows. The current logging approach is kinda dumb. The proposed new behavior isn't really spectacular. As far as I recall, there was never any further discussion (which is what I suggested to the OP) about what a good change would be.

Bring it up on the mailing list and perhaps a discussion will lead to a satisfactory answer.

[jasonjwwilliams]

Patch changes log.msg() start/stop calls in TCP and UDP protocols to use format:

log.msg(eventSource=self,

eventType="stop", protocol=self.protocol, portNumber=self._realPortNumber)

Includes tests to match.

[jasonjwwilliams]

New patch that also implements the new logging format in the doStart and doStop of t.i.protocol.AbstractDatagramProtocol. Turned out there are "starting" and "stopping" message logged in those protocols. While they were wrapped in if self.noisy, there was no way to reliably set those when doing DNS queries. This makes them adopt the new event dictionary logging output. Added unit tests for these.

[exarkun]

(In [30632]) Branching to 'non-message-startstop-log-4021'

[exarkun]

(In [30633]) Apply 4021_less_chatty.patch

refs #4021

[ralphm]

Thanks for the patch. It seems that it addresses the problem set out in this ticket, avoiding the regular logging by FileLogObserver by passing an eventDict it doesn't recognise. Fortunately this has the nice property of allowing one to write a custom log observer to still log these messages, if desirable. A few comments:

• I'm unsure about the values of eventType: start and stop. For a more general solution (which isn't within the scope of this ticket) that would include the other noisy logging (esp. for starting and stopping factories), this doesn't seem specific enough.
• I believe the dict keys and possible values should be documented.
• It would be nice to have example code and documentation for a custom log observer that consumes this dict.
• Summary lines of docstrings end in a full stop.
• Classes are separated by 3 blank lines
• Methods are separated by 2 blank lines.
• Use assertInstanceOf if you really want to use instance checks. Given that the values might also simply provide the same interface, but not derive from, Port and DatagramProtocol, this is in general a bad idea.
• Remove spurious prints.
• It seems kinda weird to add tests for unix ports that verify the current behaviour, but not do the very small extra step to make this also log a dict, even though it is slightly out of scope.

[jasonjwwilliams]

My pleasure. Regarding your comments:

* I think start and stop are a good event identifiers for now while we start to work with this new approach. Working with it in production for awhile will give us a better idea of how to name the events for filtering. For now, if you're interested in getting the start/stop verbosity back, start and stop clearly indicate you're going to get access to that. * Regarding documenting the dict keys and possible values, I'm happy to do that. Where would be the best place to place those bits? * Not sure what "Summary lines of docstrings end in a full stop" means. * I'm purposely not using assertInstanceOf, because I don't want to assert in this case. I just want to filter dicts containing the sought eventSource and protocol so dictHits can be incremented. It will allow the test to function in the presence of more logging entries than we're looking for, following the pattern of the old text-based logging tests. * I've removed the spurious print I found in test_tcp.py. * Honestly, I don't work with the UNIX ports code at all, hence the reason I didn't add the logging over there. The UNIX ports test code was modified because it inherits from the TCP logging tests, and since the UNIX code hasn't been updated it needed to be changed to use the old method. If you're up to changing the UNIX code, I think the symmetry would be nice.

[jasonjwwilliams]

Implements less chatty logging messages for TCP/UDP protocol start/stop. Logs an event dictionary.

[exarkun]

If there's a branch for a ticket, new patches should be based on the branch, not on trunk. Also replacing old attachments makes things harder too (but I think I've turned that off in trac now so hopefully you won't be able to do it anymore).

[exarkun]

(In [30763]) destroy this to start over with the newer version of the patch against trunk

refs #4021

[exarkun]

(In [30764]) Branching to 'non-message-startstop-log-4021'

[exarkun]

(In [30765]) Apply new 4021_less_chatty.patch

refs #4021

[exarkun]

(In [30766]) destroy this to start over with the newer version of the patch against trunk

refs #4021

[exarkun]

(In [30767]) Branching to 'non-message-startstop-log-4021'

[exarkun]

(In [30768]) Really apply new 4021_less_chatty.patch

refs #4021

[jasonjwwilliams]

Apologies. Will patch off the branch in the future.

[exarkun]

I made some more changes in the branch:

1. M-x whitespace-cleanup
2. test method docstrings describe what's being tested somewhat better (still not ideal)
3. UNIX sockets implemented
4. Where there's a factory being included as a value, the key is now factory instead of protocol
5. There were a lot of docstrings with trivial errors, such as ones which continued to refer to getExpectedConnectionLostLogMsg even though that method was renamed and repurposed.
6. Factored the log observer code into setUp and made sure to remove any added observer, to avoid blowing up memory by saving every log event for the whole test suite.
7. Used runReactor instead of reactor.run() to get a timeout in case the test breaks

Some problems that are left to be resolved:

1. The portNumber key is probably overly specific. UNIX sockets don't have a port number, they have a filesystem path, and the interface being bound to can be interesting as well, but isn't currently exposed. I think an "address" key would work better. UDP, TCP, and UNIX can all supply something meaningful for this key, and for IPv4 stuff you'll get the interface (the local IP being bound) as well as the port number.
2. It's hard to tell AF_INET and AF_DGRAM apart with the log structure being emitted. They're both "start" and "stop" eventTypes, but they have different keys (AF_INET gets factory, AF_DGRAM gets protocol`). I think some differentiation is in order here.
3. I think UNIX DGRAM log messages need to be changed as well (perhaps this would be fine as a separate ticket, I don't think there's anything in twisted/internet/test/ that exercises UNIX DGRAM yet).
4. I factored a helper out of a trial test case, but it needs to go somewhere better than testutils.py I think. That was just an expedient place to put it while I addressed the other issues.
5. There's still a fair amount of duplication between some of the tests being modified, it might be nice if they could share some more code.

[exarkun]

Also, don't forget to add the "review" keyword to the ticket when it's ready for someone to look at!

[jasonjwwilliams]

Changed portNumber to generic address on log messages in format "host:port".

• Removed "portNumber" field on log messages.
• Added "address" field on log messages in format "host:port":
  • UNIX sockets use the same format ":filename"
• Added "eventTransport" field on log messages:
  • tcp: AF_INET
  • udp: AF_DGRAM
  • unix: UNIX sockets

[jasonjwwilliams]

Changed portNumber to generic address on log messages in format "host:port" & added eventTransport field.

[exarkun]

is that patch backwards?

[jasonjwwilliams]

Changed portNumber to generic address on log messages in format "host:port" & added eventTransport field.

[jasonjwwilliams]

Sorry...yes it was backwards. Should be right now.

[exarkun]

(In [30884]) Apply 4021_address_eventTransport.2.patch

refs #4021

[exarkun]

For the record, while I'm not sure what I was thinking as I was typing AF_INET and AF_DGRAM in that earlier comment, I think that what I meant was SOCK_STREAM vs SOCK_DGRAM.

[exarkun]

1. It would be better to use address objects for the address key in the event. Strings are blaugh. getHost will help.
2. AbstractDatagramProtocol should include a real address, not just "", in its messages
3. Don't use ... if ... else ... in Twisted. Also these uses of that syntax all seem unnecessary anyway. They are all exactly equivalent to the trivial translation to ... or ...
4. The UDP messages still just emit a portNumber instead of a full address.
5. DictSubsetMixin still needs to go somewhere else

Thanks for your continuing efforts on this.