On 10/14/10 04:46 PM, Ginnie Wray wrote:
Hi -
Three things are playing into what's going on...
1. The logger init
2. Tests run with vs. without the engine.
3. The reset_engine function in engine_test_utils.py (not really part
of the current problem but part of the solution)
The logger setting up a FileHandler presents a problem in that
every time getLogger is called, the __init__ of InstallLogger is
executed. That's why Dermot was seeing output twice.
The problem I found with moving the FileHandler code as Karen and I
suggested is that everytime getLogger is called with a new child
logger, a FileHandler is added to the child. This results in
propagating a FileHandler to every child created. When the child logs
a message, the log message first logs using the child's FileHandler
and then checks for a parent and logs to the parent handler, even
though it's the same file. Thus the double output .(Engine logger +
checkpoint logger)
The problem with checking for the existence of the default log
prevents a FileHandler from being created, resulting in missing output.
Dermot's non-engine code tests worked before because he was generating
his own LOGGER instead of using self.logger. Now that he is using
self.logger, when the tests that run w/o the engine are executed, they
won't have a handler associated with them, since the InstallLogger
sets up the default file handler.
My suggestion for how to solve this involves a couple of things.
1. For tests that are run without the engine, they should set up the
InstallLogger class in the setUp function of the unit tests. That way
the functionality of the InstallLogger is available, even w/o the engine.
So the non-engine test code would need to add:
from solaris_install.logger import InstallLogger
def setUp(self):
'''DEBUG'''
logging.setLoggerClass(InstallLogger)
maybe a teardown as well. That doesn't seem to be a problem though,
because the python logger does checking for this.
2. I would like to change the logger.py code to check to see if the
InstallLogger.ENGINE param is set. If not, execute the default
FileHandler creation. If it is, skip it. This solves the double output
issue. Instead of the check to see if the log path exists, I'll add a
check for the following:
if self.ENGINE is None:
add filehandler code
What if instead, the Engine were in charge of configuring the default
file handler? I think that might more cleanly solve the problem, and it
also allows the logging code to be more agnostic to the execution
environment.
This might also mean that (1) from above wouldn't be necessary (though I
haven't tried it).
3. In the engine_test_utils.py, reset_engine function, we should also
set the InstallLogger.ENGINE variable back to None. That will enable
item 2 to work properly.
from solaris_install.logger import InstallLogger
InstallLogger.ENGINE = None
Perhaps that should be in InstallLogger.close()? (For that matter,
perhaps some of the other logging related cleanup in reset_engine()
should be in InstallLogger.close()?)
- Keith
I made these changes and ran Dermot's tests, and I think it works. I
have a defaultlog on Indiana-Build in
/var/tmp/install/default_log.26802. Dermot, do you want to take a look
and see if it's complete?
thanks,
ginnie
On 10/14/10 07:22, Dermot McCluskey wrote:
Karen,
You are definitely on to something here. However, when I made your
change to logger.py and re-ran my tests I seem to be getting output for
all tests logged to /var/tmp/install/default* correctly, but the
output from
my checkpoints is getting logged twice, while the ouptut from the
InstallEngine just gets logged once, eg:
2010-10-14 11:23:16,772 InstallationLogger DEBUG Spawning
InstallEngine execution thread
2010-10-14 11:23:16,772 InstallationLogger DEBUG Snapshotting
DOC to /tmp/engine_test_doc_path_13995/.data_cache.manifest_parser
2010-10-14 11:23:16,772 InstallationLogger DEBUG Executing
manifest_parser checkpoint
2010-10-14 11:23:16,772 InstallationLogger.manifest_parser
DEBUG ManifestParser.execute(dry_run=False) called
2010-10-14 11:23:16,772 InstallationLogger.manifest_parser
DEBUG ManifestParser.execute(dry_run=False) called
etc
(This is after I have changed my code to use self.logger.)
- Dermot
On 10/13/10 21:14, Karen Tung wrote:
On 10/13/10 06:00, Dermot McCluskey wrote:
parser.py: lines 145-148. Since this is the entry point when
invoked from the engine, shouldn't simply using self.logger
work? FWIW, the DC checkpoints used to do something like what
you have here but we changed it to simply use self.logger and
that works just as well.
I agree with Alok that MP/MW should use self.logger to log messages.
That will allow messages to be "tagged" correctly with the MP/MW
checkpoint name.
When I try that and re-run all my unit tests, only the output from
one of the
24 tests is in the log - all the other logging output is missing.
Any idea
what's going on here?
I've also noticed that even without making this change, some (but
not all)
of the output from my full set of unit tests is missing from the
log. It seems
that tests that use the InstallEngine are not logging, *if* those
tests are run
after some other tests that log output.
I looked at the log files in /var/tmp/install from running the
engine tests,
and I also noticed that only log outputs from one of the tests show up.
Log output from other tests are missing.
I did some digging around, and I think it is caused by the following
code in usr/src/lib/install_logging_pymod/logger.py:
197 # Create the default log
198 # if not os.path.exists(DEFAULTLOG):
199 # filehdlr = FileHandler(filename=DEFAULTLOG,
mode='a')
200 # filehdlr.setLevel(DEFAULTLOGLEVEL)
201 # filehdlr.setFormatter(InstallFormatter())
202 # logging.Logger.addHandler(self, filehdlr)
203 # filehdlr.addFilter(self._prog_filter)
204
205 filehdlr = FileHandler(filename=DEFAULTLOG, mode='a')
206 filehdlr.setLevel(DEFAULTLOGLEVEL)
207 filehdlr.setFormatter(InstallFormatter())
208 logging.Logger.addHandler(self, filehdlr)
209 filehdlr.addFilter(self._prog_filter)
Just for experiment, I commented out the original code block, and
removed
the "if" statement. With that change, I get log output from all the
tests. Since the name of DEFAULTLOG
is based on pid, and different tests cases are running under the
same pid, the default
file handler is not added except for the 1st test case.
I am not sure simply removing the check is the right thing to do.
We might not
want to overwrite an existing file.
Do you have any examples where you have run more than one unit test
file, with more than one test per file, where all the tests log
something?
It would be very helpful to have a template of how to initialize
and reset
logging, in Engine checkpoints, non-Engine code, and unit tests.
Do you
know if such examples exist?
parser.py: line 229: What use case does the cancel_requested
handle?
I'm not sure if I understand the question correctly, but this will
be invoked
in the user requested Cancel since the previous check, ie during
the call
to _load_manifest(). I think Karen specifically requested I add
this one
during her review.
I requested Dermot to add the check, because I _load_manifest()
could be a relative long operation, depending on the size of the
manifest
to load. So, it would be good to check whether user requested cancel.
Thanks,
--Karen
_______________________________________________
caiman-discuss mailing list
[email protected]
http://mail.opensolaris.org/mailman/listinfo/caiman-discuss
_______________________________________________
caiman-discuss mailing list
[email protected]
http://mail.opensolaris.org/mailman/listinfo/caiman-discuss
_______________________________________________
caiman-discuss mailing list
[email protected]
http://mail.opensolaris.org/mailman/listinfo/caiman-discuss
