classification
Title: Python exception on strftime with %f on Python 3 and Python 2 on windows
Type: Stage: resolved
Components: Library (Lib), Windows Versions: Python 3.5, Python 3.4
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: MajeedArni, eryksun, ned.deily, python-dev, r.david.murray, steve.dower, tim.golden, yselivanov, zach.ware
Priority: normal Keywords: patch

Created on 2015-05-20 04:37 by MajeedArni, last changed 2015-06-24 03:49 by python-dev. This issue is now closed.

Files
File name Uploaded Description Edit
24244_1.patch steve.dower, 2015-05-20 16:33 review
Messages (42)
msg243641 - (view) Author: Majeed Arni (MajeedArni) Date: 2015-05-20 04:37
http://bugs.python.org/issue11735 fixed in 2.7, but in 3.4 and 3.5 the same problem exists. Just crashes python.
msg243646 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-05-20 05:48
Please follow Ned's suggestion that prompted you to open this issue and report the exact version of python, your OS, and how to reproduce it.  I cannot reproduce it based on the existing issues using python 3.4.1 on Windows 7.
msg243661 - (view) Author: Eryk Sun (eryksun) * Date: 2015-05-20 13:34
> I cannot reproduce it based on the existing issues using python 
> 3.4.1 on Windows 7.

Majeed could be referring to the ValueError that gets raised for this [only on Windows][1]. In Linux %f passes through silently. Maybe for 3.5 an alternate approach would be to disable the Windows CRT's invalid parameter handler using _Py_BEGIN_SUPPRESS_IPH and _Py_END_SUPPRESS_IPH.

Looking at this brought issue 10653 to my attention. It seems VC++ 14 has exacerbated that problem, but that the current solution no longer works even in 3.4.3 with VC++ 10. Should the issue be reopened or a new issue opened? 

[1]: https://hg.python.org/cpython/file/413e0e0004f4/Modules/timemodule.c#l611
msg243663 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-05-20 13:44
The ValueError is not a bug.  Not all format codes are supported on all platforms (we start from what the platform supports, and then we have a few we have implemented cross platform, but that isn't one of them).  We also pass through the behavior of the underlying system as far as handling unknown codes.  Whether that is the best policy or not is an interesting question, but one that should probably be addressed on python-ideas if someone wants to tackle it, since it has backward compatibility implications (and the wider discussion would affect the the behavior on FreeBSD as well, where unknown codes are handled differently than they are on linux, though they don't produce an exception.)

For the other I think you should open a new issue referencing the old one.
msg243664 - (view) Author: Majeed Arni (MajeedArni) Date: 2015-05-20 13:54
When we have this for format:
    date_format = '%Y %m %d %H:%M:%S %z'
I see our logs as:
[2015 05 19 17:36:09 -0500] watcher modified

When I change the format to:
[2015 05 20 08:51:24 -0500] stderr AttributeError: 'StreamLogger' object has no attribute 'flush'

Unhandled exception in thread started by
msg243667 - (view) Author: Majeed Arni (MajeedArni) Date: 2015-05-20 14:02
Actually it is happening in Python 2.7 too..

Here is the format we are trying to use:

 date_format = '%Y %m %d %H:%M:%S:%f %z'

Also, is there something millisecond if not microsecond?
msg243669 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-05-20 14:08
So, this is expected behavior on Windows.  I'm inclined to close the issue as not a bug unless the Windows folks think eryksun suggestion is worth considering.  (If the error is suppressed, does windows fill in the rest of the values and just leave the %f in the string?)
msg243671 - (view) Author: Eryk Sun (eryksun) * Date: 2015-05-20 14:18
> If the error is suppressed, does windows fill in the rest of 
> the values and just leave the %f in the string?

No, it does not. I understand now why ValueError was an intentional choice here. The CRT actually breaks the loop with a goto if any call to expand_time fails. So raising a Python exception is the only reasonable course of action. (I still think maybe it's a good place to use the new _Py_BEGIN_SUPPRESS_IPH macro. That way instead of presuming what's a valid format code, it could just handle the EINVAL.)
msg243678 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-05-20 16:33
_Py_*_SUPPRESS_IPH is the right thing to use here. It still displays an assertion dialog in debug builds, but ignoring it has the correct effect.

Patch attached for 3.5
msg243690 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-05-20 19:51
What's the behavior after this patch?  Does it just return the string unmodified?  Or return a null string?  Or is the traceback generated at a higher level (and if so what is the error message?)
msg243693 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-05-20 21:00
It raises ValueError just like now (no visible change), but it won't crash and doesn't require being able to validate the complete format string.

If we want any different behaviour, we need to reimplement strftime for Python, which I'd be okay with, but I'm not the one to do it :)
msg243696 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-05-20 21:06
OK.  What made me wonder is that I saw that the 'invalid format string' exception was removed by the patch...I guess that is also raised at a higher level in the code.
msg243698 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-05-20 21:29
It's raised by the existing handling for EINVAL at the end of the function. Previously we'd crash before getting that far because of the invalid parameter handler.
msg243856 - (view) Author: Roundup Robot (python-dev) Date: 2015-05-22 22:08
New changeset 254b8e68959e by Steve Dower in branch 'default':
Issue 24244: Prevents termination when an invalid format string is encountered on Windows.
https://hg.python.org/cpython/rev/254b8e68959e
msg243858 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-05-22 22:18
That handles Python 3.5 and future versions, even if the supported formats change.

Is there something that needs fixing in 3.4? I don't get a crash, just the ValueError...
msg244172 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2015-05-27 15:04
timemodule.c no longer compiles on MacOSX:


gcc -Wno-unused-result -Wsign-compare -Wunreachable-code -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes -Werror=declaration-after-statement -I./Include -I. -IInclude -I/usr/local/include -I/Users/yury/dev/py/cpython/Include -I/Users/yury/dev/py/cpython -c /Users/yury/dev/py/cpython/Modules/timemodule.c -o build/temp.macosx-10.10-x86_64-3.5/Users/yury/dev/py/cpython/Modules/timemodule.o
/Users/yury/dev/py/cpython/Modules/timemodule.c:656:9: error: use of undeclared identifier '_Py_BEGIN_SUPPRESS_IPH'
        _Py_BEGIN_SUPPRESS_IPH
        ^
/Users/yury/dev/py/cpython/Modules/timemodule.c:658:9: error: use of undeclared identifier '_Py_END_SUPPRESS_IPH'
        _Py_END_SUPPRESS_IPH
        ^
2 errors generated.
msg244176 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-05-27 15:18
That change was in for beta 1, so we would have noticed if we didn't get Mac builds.

Something else has changed, probably some headers.
msg244180 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2015-05-27 15:42
Yury, I'm not seeing that compile error with current head of default on OS X. Try a clean build, perhaps?
msg244182 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2015-05-27 15:45
This exact sequence of commands

$ make clean
$ ./configure
$ make -j8

does not build.
msg244184 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2015-05-27 15:49
$ hg status
shows nothing, branch is default (but 3.5 doesn't get built either) etc.
msg244185 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2015-05-27 15:56
I think you have a Python installed in /usr/local that is interfering.
msg244186 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2015-05-27 15:56
But why was it building just fine before this commit? I haven't updated my system packages in a while.
msg244187 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-05-27 15:56
Those macros are only included if Py_BUILD_CORE is defined, regardless of platform (see Include/pyport.h).

Is it possible that's being undefined somehow?
msg244189 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2015-05-27 16:02
Wild guess: perhaps you did a ./configure or the Makefile did an implicit call to configure recently and/or you did a make install (to /usr/local) before?
msg244190 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2015-05-27 16:04
> Wild guess: perhaps you did a ./configure or the Makefile did an implicit call to configure recently and/or you did a make install (to /usr/local) before?

I don't have 'python' in /usr/local and /usr/local/bin
msg244191 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2015-05-27 16:05
But do you have any Python header files in /usr/local/include?  The gcc command you pasted shows -I/usr/local/include?  Mine don't show that.
msg244192 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2015-05-27 16:07
yury@ysmac ~/dev/py/cpython (HG: default?) $ ls /usr/local/include/
librtmp osxfuse pycairo
msg244193 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2015-05-27 16:11
FWIW, I think that in order to use _Py_BEGIN_SUPPRESS_IPH timemodule.c should be compiled with PY_CORE_CFLAGS, and that should be reflected in the Makefile.
msg244194 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-05-27 16:16
Looking at a `grep PY_CORE_CFLAGS`, that sounds reasonable to me.

I assumed that all core files were already being compiled with Py_BUILD_CORE (they certainly are for Windows), so this seems to be an oversight for timemodule.c.
msg244196 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2015-05-27 16:33
Steve, maybe you can surround "_Py_BEGIN_SUPPRESS_IPH" with "#ifdef Py_BUILD_CORE"?
msg244197 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2015-05-27 16:51
Yury, another (less) wild guess: do you have an out-of-date Modules/Setup or Setup.local?  timemodule is defined in Setup.dist but that will be overridden by a locally modified copy in the Modules directory.  Towards the end of the configured top-level Makefile, you should see:

# Rules appended by makedepend

[...]

Modules/timemodule.o: $(srcdir)/Modules/timemodule.c; $(CC) $(PY_CORE_CFLAGS)  -c $(srcdir)/Modules/timemodule.c -o Modules/timemodule.o
msg244198 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-05-27 16:51
When do we build timemodule.c outside of core?
msg244199 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2015-05-27 16:54
> Towards the end of the configured top-level Makefile, you should see:

Yes, I don't see that line.  What should I do to regenerate it?  And another question: what did go wrong with my checkout?
msg244200 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2015-05-27 16:55
Check the times and contents on all of your Modules/Setup* files.  Try deleting Setup.local for one.
msg244201 - (view) Author: Majeed Arni (MajeedArni) Date: 2015-05-27 17:07
Though %f is a valid format from Python's doc https://docs.python.org/2/library/datetime.html, the fix just ignores it on Windows? can we atleast get milliseconds on Windows and Micro on Linux?

%f 	Microsecond as a decimal number, zero-padded on the left. 	000000, 000001, ..., 999999 	(4)

%f is an extension to the set of format characters in the C standard (but implemented separately in datetime objects, and therefore always available). When used with the strptime() method, the %f directive accepts from one to six digits and zero pads on the right.

New in version 2.6.
msg244202 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2015-05-27 17:12
> Check the times and contents on all of your Modules/Setup* files.  Try deleting Setup.local for one.

I just made a clean checkout and that helped.  I have no idea what caused this.  Thank you, Ned, for troubleshooting this with me!
msg244203 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-05-27 17:26
Note that when I run into build problems after an update, I generally run 'make distclean' and then redo the configure/make.  This generally cleans up any problems like this (and I don't find that I need to do it very often.)
msg244204 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2015-05-27 17:35
> Note that when I run into build problems after an update, I generally
> run 'make distclean' and then redo the configure/make.

Yes, but I believe that won't help with changed Modules/Setup* files and, because it is needed in the core interpreter executable, timemodule.c is supposed to be built using Setup and not setup.py.  Setup and Setup.local are designed to be locally modified and thus not revision controlled nor cleaned by make clean:

$ cat Modules/Setup.dist
# The file Setup is used by the makesetup script to construct the files
# Makefile and config.c, from Makefile.pre and config.c.in,
# respectively.  The file Setup itself is initially copied from
# Setup.dist; once it exists it will not be overwritten, so you can edit
# Setup to your heart's content.  Note that Makefile.pre is created
# from Makefile.pre.in by the toplevel configure script.
[...]
$ hg stat --all Modules
I Modules/Setup
I Modules/Setup.config
I Modules/Setup.local
msg244206 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-05-27 17:41
Right, that's why I said make *dist*clean.  That does delete any existing Setup file(s), which is what you want when working with a checkout for Python development purposes.
msg244207 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2015-05-27 17:44
So you did, sorry!  Another, perhaps evan more reliable option is (requires enabling the purge extension in hg):

hg purge --all
msg245710 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2015-06-24 03:44
Finally got back to looking at this, and since %f works against MSVC 14.0 I'm just going to remove the part of the test that is currently failing and close this issue.
msg245712 - (view) Author: Roundup Robot (python-dev) Date: 2015-06-24 03:49
New changeset 2c10e9f62613 by Steve Dower in branch '3.5':
Closes #24244: Removes invalid test from test_time
https://hg.python.org/cpython/rev/2c10e9f62613

New changeset f0ca1fabb41f by Steve Dower in branch 'default':
Closes #24244: Removes invalid test from test_time
https://hg.python.org/cpython/rev/f0ca1fabb41f
History
Date User Action Args
2015-06-24 03:49:09python-devsetstatus: open -> closed
resolution: fixed
messages: + msg245712

stage: resolved
2015-06-24 03:44:12steve.dowersetmessages: + msg245710
2015-05-27 17:44:03ned.deilysetmessages: + msg244207
2015-05-27 17:41:02r.david.murraysetmessages: + msg244206
2015-05-27 17:35:39ned.deilysetmessages: + msg244204
2015-05-27 17:26:56r.david.murraysetmessages: + msg244203
2015-05-27 17:12:39yselivanovsetpriority: critical -> normal

messages: + msg244202
2015-05-27 17:07:28MajeedArnisetmessages: + msg244201
2015-05-27 16:55:43ned.deilysetmessages: + msg244200
2015-05-27 16:54:53yselivanovsetmessages: + msg244199
2015-05-27 16:51:43steve.dowersetmessages: + msg244198
2015-05-27 16:51:29ned.deilysetmessages: + msg244197
2015-05-27 16:33:02yselivanovsetmessages: + msg244196
2015-05-27 16:16:19steve.dowersetmessages: + msg244194
2015-05-27 16:11:48yselivanovsetmessages: + msg244193
2015-05-27 16:07:25yselivanovsetmessages: + msg244192
2015-05-27 16:05:40ned.deilysetmessages: + msg244191
2015-05-27 16:04:06yselivanovsetmessages: + msg244190
2015-05-27 16:02:32ned.deilysetmessages: + msg244189
2015-05-27 15:56:55steve.dowersetmessages: + msg244187
2015-05-27 15:56:50yselivanovsetmessages: + msg244186
2015-05-27 15:56:00ned.deilysetmessages: + msg244185
2015-05-27 15:49:38yselivanovsetmessages: + msg244184
2015-05-27 15:45:16yselivanovsetmessages: + msg244182
2015-05-27 15:42:03ned.deilysetnosy: + ned.deily
messages: + msg244180
2015-05-27 15:18:52steve.dowersetmessages: + msg244176
2015-05-27 15:04:50yselivanovsetpriority: normal -> critical
nosy: + yselivanov
messages: + msg244172

2015-05-22 22:18:25steve.dowersetmessages: + msg243858
2015-05-22 22:08:59python-devsetnosy: + python-dev
messages: + msg243856
2015-05-20 23:42:25eryksunsetcomponents: + Windows
2015-05-20 21:29:50steve.dowersetmessages: + msg243698
2015-05-20 21:06:57r.david.murraysetmessages: + msg243696
2015-05-20 21:00:42steve.dowersetmessages: + msg243693
2015-05-20 19:51:31r.david.murraysetmessages: + msg243690
2015-05-20 16:33:21steve.dowersetfiles: + 24244_1.patch
keywords: + patch
messages: + msg243678
2015-05-20 14:18:00eryksunsetmessages: + msg243671
components: - Windows
versions: - Python 2.7
2015-05-20 14:08:50r.david.murraysettitle: Python Crash on strftime with %f on Python 3 and Python 2 -> Python exception on strftime with %f on Python 3 and Python 2 on windows
nosy: + tim.golden, zach.ware, steve.dower

messages: + msg243669

components: + Windows
2015-05-20 14:02:20MajeedArnisetversions: + Python 2.7
messages: + msg243667
title: Python Crash on strftime with %f on Python 3 -> Python Crash on strftime with %f on Python 3 and Python 2
2015-05-20 13:54:59MajeedArnisetmessages: + msg243664
2015-05-20 13:44:56r.david.murraysetmessages: + msg243663
2015-05-20 13:34:28eryksunsetnosy: + eryksun
messages: + msg243661
2015-05-20 05:48:27r.david.murraysetnosy: + r.david.murray
messages: + msg243646
2015-05-20 04:37:46MajeedArnicreate