Logging: Am I Doing It Wrong?

In my current main project, I want all of my game’s output to be logged to file–and ideally all to a single file. It seems to me that, should I want to get output from users, log-files are likely to be much more convenient for them and more reliable for me–and much more so if there’s only one file to locate and send.

However, I’m really not sure that I’m approaching logging in a sensible manner, and could use some feedback and/or advice, please.

Here is what I’m currently doing:
I’m setting “Notify”'s output-stream pointer to a MultiplexStream that I instantiate, then setting “sys.stdout” and “sys.stderr” to new file-objects. All of the above point to the same file.

Like so:

Common.nout = MultiplexStream()
Notify.ptr().setOstreamPtr(Common.nout, 0)
Common.nout.addFile(Filename(USER_DIR + "/logfile.txt"))

sys.stdout = open(USER_DIR + "/logfile.txt", "w")
sys.stderr = open(USER_DIR + "/logfile.txt", "w")

However, is it wise to have–presumably–three separate objects writing to the same file? I could perhaps use a single file-object for the two “sys”-variables, but I don’t know whether that’s a good idea, either. And indeed, I think that I’ve seen some cases of lines seeming to be cut off in part.

Furthermore, even the above doesn’t seem to catch quite everything–I believe that I’ve seen at least some output still being printed to terminal, and not ending up in the file.

So, is there a better way to go about this?

There are a few ways to go about logging. I’d recommend choosing one way and stick to it and not split it up to various loggers, especially things like print calls are simply not designed for real logging. In my earlier projects I used a dual approach of redirecting Panda3Ds output to one file and then only used pythons logging module for my personal game logs, but in the future I’m planing on using the Notifier class (Panda3Ds logging system) more often instead of pythons logging module.

With the Notifier system, you could simply create new categories for all your classes or however granular you need it with something like this:

notify = DirectNotifyGlobal.directNotify.newCategory("YourCategoryName")
# And use it like this. debug could also be error or warning for different log levels
notify.debug("some message")
# Very useful for checking which functions got called at which point in time
notify.debugStateCall()

Another plus is, that you can set the configuration of the categories from within the prc config files.

I’m not that fond of file handling with multiple pointers to one file, but I guess it’s not the best you could do. It either has to wait until one write call is done and could slow down the writing process dramatically or another possibility is, that the write calls simply interfere with one another resulting in jagged lines in the outfile.

In theory that should be sufficient to get Panda3Ds output to the log file. If there still is some terminal output, check if it’s really that of Panda3D and maybe show it here that we can check the cause of it being written to terminal rather then the log file.

I think that I tried the Notifier class at some point, and again found some (non-“print”) output being missed. Perhaps it was things like Python exceptions, the output of which might be important to have in the case of crashes!

I think that I have seen this, indeed. :/

I’m still seeing the following, at the least:

Known pipe types:
  glxGraphicsPipe
(all display modules loaded.)
:device(warning): /dev/input/event6 is not readable, some features will be unavailable.

Hm, do you have an example of a python method or class that creates such an exception output? I guess it’s not your own code, is it? Otherwise, just add a log call that you pass the exception to it, usually all log systems can handle that using the error log level call.

You need to call it prior to initializing showbase for those messages to go in the log file.

It is my code, but I’m thinking more of unexpected exceptions; bugs and crashes not foreseen. (And, now considering that, of not wanting to put near-absolutely everything in try-except blocks. ^^; )

Ah, right, of course–that was a silly mistake! Thank you for catching that. ^^;

If you don’t want to use an application wide try block, you could either register an atexit function or overwrite the exception handler. Here’s a simple sample of how to do so:

import sys
import atexit

# atexit way...
def myfunc():
    print(" - After exception handler - ")
    # use sys.last_* for exception info. May not be set!
    print(sys.last_type, sys.last_value, sys.last_traceback)
atexit.register(myfunc)

# exception hook way...
def myExHandler(ex_type, ex_value, ex_traceback):
    print(" - Custom exception handler for uncought exceptions - ")
sys.excepthook = myExHandler

# our test exception
raise Exception("Custom Exception")