Python: using a specific date format in a logger Formatter crashes Blender on Windows #50021

New Issue

Rainer Trummer · 2016-11-14T10:33:17+01:00

Rainer Trummer commented

2016-11-14 10:33:17 +01:00

I've started working with logging thanks to Sybrens presentation at BCon16. Today, I ran into a strange issue. On Linux, the code below works as expected, and gives me (what I think) nicely formatted log messages. However, on Windows, Blender (2.78a) closes immediately.

Now the strange part: If you remove the following part of the code below, the formatter works fine on Windows too:datefmt = '%D.%M.%Y, %H:%M:%S'
It seems like something in this formatting code causes a complete Blender shutdown, and only on Windows.

This is the full code, it can be run from a Blender Text Editor:

import logging, os

#    prepare a logger
def get_logger():
	#    add a logger and set it to Debug level (for the file handler)
	__logger__ = logging.getLogger(__package__)
	__logger__.setLevel(logging.DEBUG)

	- TODO: the formatter crashes Blender on Windows
	- it happens when trying to use a date format
	_formatter = logging.Formatter(fmt = '%(levelname)-8s | %(asctime)s | %(name)s.%(module)s, line %(lineno)d \n           %(message)s\n', datefmt = '%D.%M.%Y, %H:%M:%S')

	_streamHandler = logging.StreamHandler()
	_streamHandler.setFormatter(_formatter)
	_streamHandler.setLevel(logging.WARNING)
	__logger__.addHandler(_streamHandler)

	try:
		_handler = logging.FileHandler(os.path.expanduser("~/%s.txt" % __package__), mode = 'w')
		_handler.setFormatter(_formatter)
		__logger__.addHandler(_handler)
	except Exception as exc:
		__logger__.error('could not initialize file logging: %s' % exc)

	__logger__.info('logger initialized')

	return __logger__

__logger__ = get_logger()

OS Windows 7, 64 bit, crashing
OS Ubuntu Gnome 16.04, working fine

I've started working with logging thanks to Sybrens presentation at BCon16. Today, I ran into a strange issue. On Linux, the code below works as expected, and gives me (what I think) nicely formatted log messages. However, on Windows, Blender (2.78a) closes immediately. Now the strange part: If you remove the following part of the code below, the formatter works fine on Windows too:**datefmt = '%D.%M.%Y, %H:%M:%S'** It seems like something in this formatting code causes a complete Blender shutdown, and only on Windows. This is the full code, it can be run from a Blender Text Editor: ``` import logging, os # prepare a logger def get_logger(): # add a logger and set it to Debug level (for the file handler) __logger__ = logging.getLogger(__package__) __logger__.setLevel(logging.DEBUG) - TODO: the formatter crashes Blender on Windows - it happens when trying to use a date format _formatter = logging.Formatter(fmt = '%(levelname)-8s | %(asctime)s | %(name)s.%(module)s, line %(lineno)d \n %(message)s\n', datefmt = '%D.%M.%Y, %H:%M:%S') _streamHandler = logging.StreamHandler() _streamHandler.setFormatter(_formatter) _streamHandler.setLevel(logging.WARNING) __logger__.addHandler(_streamHandler) try: _handler = logging.FileHandler(os.path.expanduser("~/%s.txt" % __package__), mode = 'w') _handler.setFormatter(_formatter) __logger__.addHandler(_handler) except Exception as exc: __logger__.error('could not initialize file logging: %s' % exc) __logger__.info('logger initialized') return __logger__ __logger__ = get_logger() ``` **OS** Windows 7, 64 bit, *crashing* **OS** Ubuntu Gnome 16.04, *working fine*

Rainer Trummer commented

2016-11-14 10:33:17 +01:00

Changed status to: 'Open'

Rainer Trummer commented

2016-11-14 10:33:17 +01:00

Added subscriber: @RainerTrummer

Bastien Montagne commented

2016-11-18 18:08:02 +01:00

Added subscriber: @mont29

Bastien Montagne commented

2016-11-18 18:08:02 +01:00

Please try to reproduce this issue with vanilla python 3.6 for windows, this totaly sounds like python bug, not Blender bug…

Bastien Montagne commented

2016-12-02 10:07:12 +01:00

Changed status from 'Open' to: 'Archived'

Bastien Montagne closed this issue

2016-12-02 10:07:12 +01:00

Bastien Montagne self-assigned this 2016-12-02 10:07:12 +01:00

Bastien Montagne commented

2016-12-02 10:07:12 +01:00

More than a week without reply. Due to the policy of the tracker archiving for until required info/data are provided.

Rainer Trummer commented

2016-12-02 12:07:10 +01:00

Wasn't able to reply before as client projects kept me busy, sorry for the inconvenience.

Tried with Vanilla Python today, version 3.5.2, on the same machine where Blender crashes. Created both a file handler and stream handler for the logger, set the formatting as before, tried logging, all from interactive console. NO crash there.

Log output as desired:

Formatter used:

Wasn't able to reply before as client projects kept me busy, sorry for the inconvenience. Tried with Vanilla Python today, version 3.5.2, on the same machine where Blender crashes. Created both a file handler and stream handler for the logger, set the formatting as before, tried logging, all from interactive console. NO crash there. Log output as desired: ![output.JPG](https://archive.blender.org/developer/F412985/output.JPG) Formatter used: ![formatter.JPG](https://archive.blender.org/developer/F412984/formatter.JPG)

Bastien Montagne commented

2016-12-02 12:47:03 +01:00

Changed status from 'Archived' to: 'Open'

Bastien Montagne reopened this issue

2016-12-02 12:47:03 +01:00

Bastien Montagne commented

2016-12-02 12:47:03 +01:00

Hmm… we are going to update to py3.5.2 in coming days, but so far Blender was released with py3.5.1, and 3.5.2 seems to include some datetime fixes. So can try to confirm issue is not reproducible with vanilla py3.5.1 under windows as well?

Vuk Gardašević commented

2016-12-02 12:53:00 +01:00

Added subscriber: @VukGardasevic

Vuk Gardašević commented

2016-12-02 12:53:00 +01:00

Can you also check if the Experimental VS 2015 builds from https://builder.blender.org/download/ crash for you?

Rainer Trummer commented

2016-12-02 14:36:23 +01:00

@VukGardasevic I've tested a version which I compiled on the 23rd of November (reports as 2.78.4), it crashes, but with some more latency. Testing VS2015 build, downloaded right now: WORKS! no crashes there!

Ray molenkamp commented

2016-12-02 14:55:15 +01:00

Added subscriber: @LazyDodo

Ray molenkamp commented

2016-12-02 14:55:15 +01:00

I'm in the process of upgrading the windows libs, unless something unexpected causes issues the 3.5.2 libs should be available in the next few days.

Rainer Trummer commented

2016-12-02 14:55:29 +01:00

@mont29 HEAD BUMP You can close the report I guess. For one, the crash doesn't appear in newer Python versions, but further more my date format was nonsense. The formatter should have been:

_formatter = logging.Formatter(fmt = '%(levelname)-8s | %(asctime)s | %(name)s.%(module)s, line %(lineno)d \n %(message)s\n', datefmt='%d.%m.%Y, %H:%M:%S')

In other words: Instead of:

datefmt='%D.%M.%Y, %H:%M:%S'

which I had passed on initially, it should read:

datefmt='%d.%m.%Y, %H:%M:%S'

I was passing the Minutes-Variable twice (%M is Minutes, not the Month), and the %D variable (which might be the var for the full date). Not sure why the crash didn't happen on Linux, but I think everything should be safe.

@mont29 **HEAD BUMP** You can close the report I guess. For one, the crash doesn't appear in newer Python versions, but further more my date format was nonsense. The formatter should have been: _formatter = logging.Formatter(fmt = '%(levelname)-8s | %(asctime)s | %(name)s.%(module)s, line %(lineno)d \n %(message)s\n', datefmt='%d.%m.%Y, %H:%M:%S') In other words: Instead of: datefmt='**%D.%M.%Y**, %H:%M:%S' which I had passed on initially, it should read: datefmt='**%d.%m.%Y**, %H:%M:%S' I was passing the Minutes-Variable twice (%M is **M**inutes, not the **M**onth), and the %D variable (which might be the var for the full date). Not sure why the crash didn't happen on Linux, but I think everything should be safe.

Bastien Montagne commented

2016-12-02 14:58:12 +01:00

Changed status from 'Open' to: 'Archived'

Bastien Montagne closed this issue

2016-12-02 14:58:12 +01:00

Bastien Montagne commented

2016-12-02 14:58:12 +01:00

Oki, then let’s consider this as settled for now (we can always reopen should the issue arise again with newest libs & builds). ;)

Ray molenkamp commented

2016-12-04 02:05:40 +01:00

Updated libs to python 3.5.2 , issue remains on the vc2013 builds, the crash is coming out of the ms c runtime though, not sure what we could do about it, it's pretty much how wcsftime deals with a bad formatter, best advise is not to use a bad formatter.

Sign in to join this conversation.