Logging via logging module

[pbertera]

This patch adds support for python logging module. This makes PyPXE compatibile with software using the logging module. This patch is backward compatible: you're not obliged to use logging in your project: each module can instantiate a local (StreamHandler](https://docs.python.org/2/library/logging.handlers.html#streamhandler) if no logger is received in the constructor.

--syslog and --syslog-port system options are added.

[psychomario]

This all looks good to me.

[psychomario]

Does the change from options = message.split(chr(0))[2: -1] to options = message.split(chr(0))[3: -1] in tftp.py fix a bug I'm unaware of?

[psychomario]

(Apologies for the repeated message)

[psychomario]

Looks like some odd merge artifact. I'll ignore it for now, and check it in testing.

[mmattioli]

@psychomario @pbertera I highlighted a few areas where the 't was preserved and sent to the logger but didn't comment on every single area where it appeared. Thoughts on preserving that? I'm thinking it should be kept for when referring back to the logs since it will visually make them easier to read but also considering removing them since the logger might mess up the output? Now that I'm typing this out perhaps we should just test and see which works better...

[psychomario]

There is a bug present in the debug lines. I'm trying to locate it now. The granularity added in #54 seems to be missing. Is this a problem with the merge from master to development?

Example:

sudo python2 pypxe-server.py --debug http --dhcp
2015-04-15 20:44:06,145 INFO Starting TFTP server...
2015-04-15 20:44:06,145 DEBUG TFTP server started in debug mode. TFTP server is using the following:
2015-04-15 20:44:06,145 DEBUG   TFTP Server IP: 0.0.0.0
2015-04-15 20:44:06,145 DEBUG   TFTP Server Port: 79
2015-04-15 20:44:06,146 DEBUG   TFTP Network Boot Directory: .
2015-04-15 19:44:06,146 INFO Starting DHCP server...
2015-04-15 19:44:06,146 DEBUG NOTICE: DHCP server started in debug mode. DHCP server is using the following:
2015-04-15 19:44:06,146 DEBUG   DHCP Server IP: 192.168.2.2
2015-04-15 19:44:06,146 DEBUG   DHCP Server Port: 67
2015-04-15 19:44:06,146 DEBUG   DHCP Lease Range: 192.168.2.100 - 192.168.2.150
2015-04-15 19:44:06,146 DEBUG   DHCP Subnet Mask: 255.255.255.0
2015-04-15 19:44:06,146 DEBUG   DHCP Router: 192.168.2.1
2015-04-15 19:44:06,146 DEBUG   DHCP DNS Server: 8.8.8.8
2015-04-15 19:44:06,146 DEBUG   DHCP Broadcast Address: <broadcast>
2015-04-15 19:44:06,146 DEBUG   DHCP File Server IP: 192.168.2.2
2015-04-15 19:44:06,147 DEBUG   DHCP File Name: pxelinux.0
2015-04-15 19:44:06,147 DEBUG   ProxyDHCP Mode: False
2015-04-15 19:44:06,147 DEBUG   Using iPXE: False
2015-04-15 19:44:06,147 DEBUG   Using HTTP Server: False
2015-04-15 19:44:06,147 INFO PyPXE successfully initialized and running

We should not be seeing the DEBUG for tftp

[psychomario]

@mmattioli I commented on one of the code blocks in reply to your comment. here. Also my comment above this one shows what it looks like. This is for stdout though, not sure how syslog will look

[mmattioli]

@psychomario I just saw, let's leave the \t for now since it makes the logs easier to read. I'm looking at the bug you just pointed out.

[psychomario]

Regarding the bug, It looks like to me that if we have a valid self.logger, we don't enforce granularity. And L102-3 of pypxe-server.py uses DEBUG if there is any value set. I propose removing L102-3, and unindenting the if self.mode_debug by one level in each {dhcp, tftp, http}.py

[pbertera]

@psychomario Yes, your right.

[mmattioli]

@pbertera @psychomario is what I found here the issue? I just want to make sure we're talking about the same thing because I don't se L102-3 of pypxe-server.py to be a problem? I could be missing or misinterpreting something so please clarify. Thanks.

[pbertera]

about the "\t" in log messages: doesn't causes big issues using a StreamHandler. But can cause encoding issues using a syslog handler: Syslog messages are displayed like:

Apr 16 01:32:31 2015-04-15 21: 27:30,048 DEBUG NOTICE: TFTP server started in debug mode. TFTP server is using the following:
Apr 16 01:32:31 2015-04-15 21: 27:30,048 DEBUG #011TFTP Server IP: 0.0.0.0

Where #011 is the \t char. IMHO not a big issue

[mmattioli]

I think we should either replace the \t with two whitespace characters `, two--or just remove it. The#011` is technically a bug and shouldn't be there.

[psychomario]

Apparently the line numbers on my local copy are screwed up. I'll hardlink to @pbertera's dev branch. So L102-3 sets the debug level (.debug() doesn't output if level isn't logging.DEBUG), but only if args.MODE_DEBUG, which is now a csv string rather than a bool.

When we get to L39-40 in tftp.py (applies to all of the submodules), the logging is already at DEBUG level, so these lines have no effect for any logging type. We never actually get to this condition anyway because for any debug string we create a self.logger, thereby falsifying the parent if.

[psychomario]

I vote for two whitespace over --. -- Isn't as clean for seperating the indent levels visually.

[pbertera]

Yes, two whitespace can be a good solution.

[mmattioli]

@psychomario I understand now. If you turn the logger on, it checks if any of the debug statements were passed in and automatically sets the mode of the logger to debug even if only one of the services are passed into the debug argument. Once it's set to debug it's passed into all of the services when their threads are started thereby making all of the services log at the debug level even if only one service was passed in to be on the debug level.

Is there a way around this? I can't seem to think of or find a clean way to keep everything within one instance of the logger while maintaining granularity for debugging.

[psychomario]

See this comment. We remove the setLevel if from pypxe-server (we don't have to, we could check for all, but that's done elsewhere already), and unindent the conditional setLevel in each of the submodules.

[pbertera]

@mmattioli seems right: we need different logger instances for each service if we wants granularity..

[mmattioli]

@psychomario if we are passing in one instance of the logger to each of the services then once any of them sets the mode to debug it will set it for all of the services because they all use one logger instance.

Part of me feels like abandoning the use of the python logger because there's no clean way to preserve granularity and if users wants to log output they can just pipe all output to a file as such

$ python pypxe-server.py --debug http --dhcp > output.txt

Doing such will also give them an on-demand opportunity to rename the log file to whatever they want.

[psychomario]

Apologies, I was wrong, I didnt realise there was only one instance.

[pbertera]

@mmattioli yes in a "standalone" usage there isn't too many advantages using the logging module. The main advantage comes when one needs to integrate PyPXE in bigger projects using that already uses the logging module.

[pbertera]

Tomorrow I'll work on it to find a more clever solution.

[psychomario]

The logging module allows for logging namespaces (getChild) which can have different levels. See the following snippet:

import logging
root = logging.getLogger()
handler = logging.StreamHandler()
formatter = logging.Formatter('%(asctime)s %(name)s %(levelname)s %(message)s')
handler.setFormatter(formatter)
root.addHandler(handler)

root.setLevel(logging.INFO)
tftp = root.getChild("tftp").setLevel(logging.DEBUG)

root.debug("ROOT")
root.getChild("tftp").debug("TFTP")

The addition of %(name)s to the format string allows more specific debug messages without manually adding them to the .debug()/.info() string.

[mmattioli]

@pbertera, while we strive to have PyPXE both a standalone solution and available as a library so that it can be used in other projects it should fall on the overarching project to handle logging. Think about it, if you wrote something and want to keep track of logging for your application then why would you want to have to check individual logs for each of the libraries you're using?

When used standalone, I think it's best to just pipe the output to a file; when used as a library I think it should fall on the overarching project to handle its own logging as PyPXE will provide the log info, there just needs to be something written to handle it if it's even desired to be captured or handled.

[mmattioli]

@pbertera, following @psychomario's proposal, would you want to rebase and recommit using namespaces? If so I'll leave this PR open so you can update it.

[psychomario]

@mmattioli While I agree with you, this PR will allow syslog logging, therefore centralizing logging.

[mmattioli]

@psychomario I'm not opposed to using the logger if we can find a clean solution; what you've found regarding namespaces looks like a solution which is why I suggested he rebase and recommit (if he rebases his development branch off of our development branch, effectively starting over, and recommits then those commits will appear in this PR which is why I said I'd leave it open)?

[pbertera]

@mmattioli @psychomario yes, seems a clean solution. tomorrow I'll work on it. I'll came back with a new commit. Thanks,

[mmattioli]

@pbertera sounds good :+1:

[mmattioli]

@pbertera I assume you closed because you're going to make a new branch off of psychomario:development since there was a recent pull and then open a new PR with that? If so, that's cool just be sure to reference this PR in your new one.