writing an incident flogfile tries to use characters not valid in a Windows filename (':')

[davidsarah]

​Ticket 1396 in Tahoe-LAFS is actually a foolscap bug:

While reporting the incident in ​#1395 on a Windows platform, the following error occurred:

[Failure instance: Traceback: <type 'exceptions.IOError'>:
[Errno 22] invalid mode ('wb') or filename:
u'C:\\tahoeclient\\logs\\incidents\\incident-2011-05-05--18:33:34Z-w2qn32q.flog'

The problem (or at least one problem) is that ':' is not valid in a Windows filename. ​This MSDN article documents the Windows filename validity rules.

Presumably we don't have any test of writing an incident flogfile. This may mean that incident reporting has always been broken on Windows (unless the flogfile naming changed?)

...

The problem is... apparently due to the time format ​here in foolscap/logging/incident.py:

TIME_FORMAT = "%Y-%m-%d--%H:%M:%S"

which is used indirectly by incident_declared to create the filename.

[davidsarah]

The bug was probably introduced in ​changeset 77d2c68, 9 months ago (released in foolscap 0.6.0). See also 111#comment:6.

[Brian Warner]

I *think* there are tests of writing incident flogfiles (they'd be in source:foolscap/test/test_logging.py if so), I'll research it more later tonight. However we don't have a windows buildbot, so maybe these tests fail on windows and we've just never noticed.

Could somebody run make test on windows and see what happens?

[Brian Warner]

Yeah, "make test TEST=foolscap.test.test_logging.Incidents.test_basic" will write an incident file under _trial_temp/logging/Incidents/basic/, and it has colons in the filename.

[davidsarah]

Replying to warner:

Yeah, "make test TEST=foolscap.test.test_logging.Incidents.test_basic" will write an incident file under _trial_temp/logging/Incidents/basic/, and it has colons in the filename.

Yep, that test fails under Windows:

$ c:/python27/python setup.py trial -s foolscap.test.test_logging.Incidents.test_basic
[...]
foolscap: 0.6.1 (c:\cygwin\home\david-sarah\tahoe\trunk\support\lib\site-packages\foolscap-0.6.1-py2.7.egg),
[...]
foolscap.test.test_logging
  Incidents
    test_basic ... [Failure instance: Traceback: <type 'exceptions.IOError'>: [Errno 22] invalid mod
e ('wb') or filename: 'C:\\cygwin\\home\\David-Sarah\\tahoe\\trunk\\_trial_temp\\logging\\Incidents\
\basic\\incident-2011-05-07--22:51:14Z-jchlapq.flog'
C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\twisted-10.2.0-py2.7-win32.egg\twis
ted\internet\defer.py:133:maybeDeferred
C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\twisted-10.2.0-py2.7-win32.egg\twis
ted\internet\utils.py:191:runWithWarningsSuppressed
C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\foolscap\t
est\test_logging.py:241:test_basic
C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\foolscap\l
ogging\log.py:210:msg
--- <exception caught here> ---
C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\foolscap\l
ogging\log.py:265:add_event
C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\foolscap\l
ogging\incident.py:35:event
C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\foolscap\l
ogging\log.py:278:declare_incident
C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\foolscap\l
ogging\incident.py:85:incident_declared
]
                                                      [FAIL]

===============================================================================
[FAIL]
Traceback (most recent call last):
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\fo
olscap\test\test_logging.py", line 243, in test_basic
    self.failUnless(l.get_active_incident_reporter())
twisted.trial.unittest.FailTest: None

foolscap.test.test_logging.Incidents.test_basic
-------------------------------------------------------------------------------
Ran 1 tests in 0.240s

FAILED (failures=1)

[davidsarah]

I changed %H:%M:%S to %H%M%S at foolscap/logging/incident.py#59 and foolscap/logging/gatherer.py#L144. That fixed the test failures on Windows (XP SP3 under VirtualBox), apart from the following which look unrelated:

===============================================================================
[SKIPPED]
new-style classes still broken

foolscap.test.test_banana.ThereAndBackAgain.test_boundMethod_newstyle
foolscap.test.test_banana.ThereAndBackAgain.test_classMethod_newstyle
foolscap.test.test_banana.ThereAndBackAgain.test_class_newstyle
foolscap.test.test_banana.ThereAndBackAgain.test_instance_newstyle
===============================================================================
[FAIL]
Traceback (most recent call last):
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\fo
olscap\test\test_negotiate.py", line 586, in <lambda>
    d.addCallbacks(lambda res: self.fail("hey! this is supposed to fail"),
twisted.trial.unittest.FailTest: hey! this is supposed to fail

foolscap.test.test_negotiate.Crossfire.test1
foolscap.test.test_negotiate.CrossfireReverse.test1
===============================================================================
[ERROR]
Traceback (most recent call last):
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\twisted-10.2.0-py2.7-win32.
egg\twisted\trial\runner.py", line 575, in loadPackage
    module = modinfo.load()
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\twisted-10.2.0-py2.7-win32.
egg\twisted\python\modules.py", line 383, in load
    return self.pathEntry.pythonPath.moduleLoader(self.name)
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\twisted-10.2.0-py2.7-win32.
egg\twisted\python\reflect.py", line 464, in namedAny
    topLevelPackage = _importAndCheckStack(trialname)
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\fo
olscap\test\test_appserver.py", line 9, in <module>
    from foolscap.appserver import cli, server, client
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\fo
olscap\appserver\client.py", line 63, in <module>
    from twisted.internet.stdio import StandardIO
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\twisted-10.2.0-py2.7-win32.
egg\twisted\internet\stdio.py", line 28, in <module>
    from twisted.internet._win32stdio import StandardIO
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\twisted-10.2.0-py2.7-win32.
egg\twisted\internet\_win32stdio.py", line 7, in <module>
    import win32api
exceptions.ImportError: No module named win32api

foolscap.test.test_appserver
===============================================================================
[ERROR]
Traceback (most recent call last):
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\fo
olscap\test\test_logging.py", line 1876, in _check
    self.compare_events(events, self._read_logfile(fn2))
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\fo
olscap\test\test_logging.py", line 219, in _read_logfile
    events.append(pickle.load(f))
  File "C:\python27\lib\pickle.py", line 1378, in load
    return Unpickler(file).load()
  File "C:\python27\lib\pickle.py", line 858, in load
    dispatch[key](self)
exceptions.KeyError: '\n'

foolscap.test.test_logging.Filter.test_basic
===============================================================================
[ERROR]
Traceback (most recent call last):
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\fo
olscap\test\test_logging.py", line 1305, in <lambda>
    d.addCallback(lambda res: gatherer.do_rotate())
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\foolscap-0.6.1-py2.7.egg\fo
olscap\logging\gatherer.py", line 204, in do_rotate
    d = utils.getProcessOutput(self.bzip, [new_name], env=os.environ)
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\twisted-10.2.0-py2.7-win32.
egg\twisted\internet\utils.py", line 124, in getProcessOutput
    reactor)
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\twisted-10.2.0-py2.7-win32.
egg\twisted\internet\utils.py", line 25, in _callProtocolWithDeferred
    reactor.spawnProcess(p, executable, (executable,)+tuple(args), env, path)
  File "C:\cygwin\home\David-Sarah\tahoe\trunk\support\Lib\site-packages\twisted-10.2.0-py2.7-win32.
egg\twisted\internet\posixbase.py", line 335, in spawnProcess
    raise NotImplementedError, "spawnProcess not available since pywin32 is not installed."
exceptions.NotImplementedError: spawnProcess not available since pywin32 is not installed.

foolscap.test.test_logging.Gatherer.test_log_gatherer
-------------------------------------------------------------------------------
Ran 452 tests in 127.593s

FAILED (skips=4, failures=2, errors=3, successes=443)

[Brian Warner]

I'm willing to change the incident filenames when we see we're running under windows, but I want to retain the readability benefit of the colons on other platforms. Foolscap itself doesn't ever try to parse those filenames: they're strictly for the benefit of humans who are looking at a directory full of Incident files and trying to decide which are worth examining.

I'll look into the other failures. Opening files in text mode probably explains some of them, but not all.

[Brian Warner]

Patched in [3fd4331] (change filenames on windows, but not elsewhere).

[Zooko]

Having the filenames differ depending on platform could lead to support problems for me. For example, someone doing support might ask a user to look for a file by a certain name, and the user might check (perhaps by "ls $NAME" so they don't even see that there is another file) and report that there is no file by that name. This is just one example--there might be other ways that this causes trouble. For example, scripts would have to be specifically written to search for both patterns or else they would appear to work on the author's platform but then silently fail when run by a user on a different platform.

Also, there is no unit test of this "if on windows" branch in the code, right? So if in the future someone writes a patch to foolscap which fails when the filename is of the other format there will be no unit test failure to let them know that their patch has a problem.

Why not eliminate the if statement and make the format be without colons on all platforms? That's uglier, but I would rather suffer that than have to maintain a divergence of behavior based on platform (especially an untested behavior).

[davidsarah]

Replying to zooko:

Having the filenames differ depending on platform could lead to support problems for me. [...] Why not eliminate the if statement and make the format be without colons on all platforms? That's uglier, but I would rather suffer that than have to maintain a divergence of behavior based on platform (especially an untested behavior).

+1. I'd really rather minimize platform-dependent behaviour, and the minor loss of readability (these filenames are not very readable anyway) from losing the ':'s on Unix does not seem like a big deal to me.

[davidsarah]

Regression in 0.6.0.

[Brian Warner]

Ok, ok, I'll compromise readability and use hyphens on all platforms. Fixed in [d4e12cc].

Non-windows users everywhere will curse window's limitations each time they glance at a flogfile or incident report filename and spend precious seconds trying to figure out which one might have occurred during the time of interest. To help them curse windows more productively, I've added "why I hate windows filenames" to an accumulation of frustration in the WhyIHateX wiki page.