Tox: TypeError: write() argument must be str, not bytes

[fschulze]

I get the following traceback when there is an error on Linux and Windows with Python 3.5.

Not sure which tox version is used. I guess the current one, because I use devpi test and it creates a fresh virtualenv.

The only info I have is:
platform win32 -- Python 3.5.2, pytest-3.0.5, py-1.4.31, pluggy-0.4.0

Traceback (most recent call last):
  File "/home/devpi/devpi/bin/devpi", line 11, in <module>
    sys.exit(main())
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/devpi/main.py", line 30, in main
    return method(hub, hub.args)
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/devpi/test.py", line 223, in main
    ret = devindex.runtox(*args)
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/devpi/test.py", line 92, in runtox
    ret = toxrunner(toxargs)
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/tox/session.py", line 39, in main
    retcode = Session(config).runcommand()
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/tox/session.py", line 375, in runcommand
    return self.subcommand_test()
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/tox/session.py", line 526, in subcommand_test
    if self.setupenv(venv):
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/tox/session.py", line 434, in setupenv
    status = venv.update(action=action)
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/tox/venv.py", line 142, in update
    action.setactivity("create", self.envconfig.envdir)
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/tox/session.py", line 96, in setactivity
    self.report.verbosity0("%s %s: %s" % (self.venvname, name, msg), bold=True)
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/tox/session.py", line 301, in verbosity0
    self.logline("%s" % msg, **opts)
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/tox/session.py", line 297, in logline
    self.tw.line("%s" % msg, **opts)
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/py/_io/terminalwriter.py", line 201, in line
    self.write(s, **kw)
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/py/_io/terminalwriter.py", line 198, in write
    write_out(self._file, markupmsg)
  File "/home/devpi/devpi/local/lib/python3.5/site-packages/py/_io/terminalwriter.py", line 333, in write_out
    fil.write(msg)
  File "/home/devpi/devpi/lib/python3.5/codecs.py", line 377, in write
    self.stream.write(data)
TypeError: write() argument must be str, not bytes

[obestwalter]

Thanks for the report @fschulze. It crashes in the py lib ... maybe the actual problem lies there? We'll see.

[obestwalter]

@fschulze where you able to collect some more info on this? I think this is a problem in py lib ...

[pjdicke]

with open(os.path.join(base, 'dist', 'deps.js'), 'w') to with open(os.path.join(base, 'dist', 'deps.js'), 'wb') got me passed the TypeError: write() argument must be str, not bytes. But still having a hard time building this thing...

Found this from here: http://stackoverflow.com/questions/13906623/using-pickle-dump-typeerror-must-be-str-not-bytes

[obestwalter]

Thanks @pjdicke - TypeError: write() argument must be str, not bytes can occur under many circumstances, but thanks for chipping in.

I think in this case the problem must occur here:

self.report.verbosity0("%s %s: %s" % (self.venvname, name, msg), bold=True)

as all arguments are turned into strings, something in verbosty0 must turn the whole thing into bytes again. I did not check myself whats going on there yet, but this is where I would start looking.

[tonybaloney]

I've spent a few hours trying to figure this out, here is where I'm up to:

The issue is within the TextIOWrapper (stdout). "TypeError: write() argument must be str, not bytes does not mean that the argument you passed was actually bytes, sys.stdout is a buffered stream with .line_buffering enabled, which means something written to the line earlier could be the bytes, not the string you just submitted.

So, the issue is that something has sent bytes to the stdout stream that shouldn't have.

My strong suspicion is that it's related to the Popen/stdout/stderr buffer for the threads that Tox instantiates. Since Tox is designed to call Python 3 and Python 2 equally, it's probably in a subprocess that's the issue, not in the main tox application.

There are 2 places that concern me, one is-
https://github.com/tox-dev/tox/blob/master/tox/session.py#L129-L146
which calls sys.stdout instead of using the stdout as overridden by the user.

The second and I _think_ the culprit (because this is almost impossible to properly debug is https://github.com/tox-dev/tox/blob/master/tox/interpreters.py#L74-L77

Here is my tox.ini

[tox]
envlist = py27, py36, lint, pylint

[testenv]
setenv =
    PYTHONPATH = {toxinidir}:{toxinidir}/retox
commands = python setup.py test

If I call my process with the environments, py27 it's fine, py36 is fine, py36,p27 is fine.

Whenever I include the environment 'lint' it crashes. Yes, I know this tox.ini doesn't make any sense because I haven't defined what the lint environment should run. It calls by default Python 3.6, because that's what my virtualenv is configured with.

The error from Tox is on invocation

tox: ERROR: InvocationError: /Users/anthonyshaw/repo/retox-2/.tox/lint/bin/python setup.py test (see /Users/anthonyshaw/repo/retox-2/.tox/lint/log/lint-108.log)

Note, my test suite is supposed to fail, I'm checking that it fails properly.

======================================================================
ERROR: __main__ (unittest.loader._FailedTest)
----------------------------------------------------------------------
ImportError: Failed to import test module: __main__
Traceback (most recent call last):
  File "/Library/Frameworks/Python.framework/Versions/3.6/lib/python3.6/unittest/loader.py", line 153, in loadTestsFromName
    module = __import__(module_name)
  File "/Users/anthonyshaw/repo/retox-2/retox/__main__.py", line 11, in <module>
    from asciimatics.screen import Screen
  File "/Users/anthonyshaw/repo/retox-2/.eggs/asciimatics-1.9.0-py3.6.egg/asciimatics/screen.py", line 24, in <module>
    from asciimatics.event import KeyboardEvent, MouseEvent
ModuleNotFoundError: No module named 'asciimatics.event'


----------------------------------------------------------------------
Ran 5 tests in 0.001s

FAILED (errors=4)
Test failed: <unittest.runner.TextTestResult run=5 errors=4 failures=0>
error: Test failed: <unittest.runner.TextTestResult run=5 errors=4 failures=0>

So, in summary if you are getting this issue, try selecting only certain environments then try running your lint/pylint etc. environments under Python 2.7 virtualenv's instead of 3+
@obestwalter

[obestwalter]

Hi @tonybaloney - thank you for digging into this one.

I started a minimal reproducer with your information here: https://github.com/obestwalter/tox-reproducers.

At the moment this does not yet trigger the error (see log). Would it be possible for you to add what is needed to reproduce it (ideally in a PR against that repo)? I did not override the test command and use pytest, because I guess these are not specific to reproduce the error. if they are ... well that would be another interesting aspect of that bug.

According to your info it should then be possible to run tox -e py27,py36,lint and trigger the exception then.

[asottile]

I'm able to reproduce a crash similar to this with the following combination:

• tox is installed in a python3 interpreter
• --result-json is passed on the commandline
• lots of -v are passed on the commandline (increasing verbosity causes a different path in running tests)

The trace looks as follows:

$ tox -e fix-lint --result-json out.json -vvv
using tox.ini: /private/tmp/tox/tox.ini
using tox-2.9.1 from /Users/asottile/opt/venv/lib/python3.6/site-packages/tox/__init__.py
GLOB start: packaging 
GLOB sdist-make: /private/tmp/tox/setup.py
  /private/tmp/tox$ /Users/asottile/opt/venv/bin/python3.6 /private/tmp/tox/setup.py sdist --formats=zip --dist-dir /private/tmp/tox/.tox/dist >/private/tmp/tox/.tox/log/tox-0.log
GLOB finish: packaging after 1.03 seconds
copying new sdistfile to '/Users/asottile/.tox/distshare/tox-2.9.2.dev52+g6dfb23a.zip'
fix-lint start: getenv /private/tmp/tox/.tox/fix-lint
fix-lint create: /private/tmp/tox/.tox/fix-lint
setting PATH=/private/tmp/tox/.tox/fix-lint/bin:/Users/asottile/bin:/usr/local/opt/findutils/libexec/gnubin:/usr/local/opt/coreutils/libexec/gnubin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin:/Applications/VMware Fusion.app/Contents/Public
  /private/tmp/tox/.tox$ /Users/asottile/opt/venv/bin/python3.6 -m virtualenv --python /usr/local/bin/python3.6 fix-lint >/private/tmp/tox/.tox/fix-lint/log/fix-lint-0.log
fix-lint finish: getenv after 2.33 seconds
fix-lint start: installpkg /private/tmp/tox/.tox/dist/tox-2.9.2.dev52+g6dfb23a.zip
fix-lint inst: /private/tmp/tox/.tox/dist/tox-2.9.2.dev52+g6dfb23a.zip
setting PATH=/private/tmp/tox/.tox/fix-lint/bin:/Users/asottile/bin:/usr/local/opt/findutils/libexec/gnubin:/usr/local/opt/coreutils/libexec/gnubin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin:/Applications/VMware Fusion.app/Contents/Public
  /private/tmp/tox$ /private/tmp/tox/.tox/fix-lint/bin/pip install /private/tmp/tox/.tox/dist/tox-2.9.2.dev52+g6dfb23a.zip[lint] >/private/tmp/tox/.tox/fix-lint/log/fix-lint-1.log
fix-lint finish: installpkg after 0.32 seconds
Traceback (most recent call last):
  File "/Users/asottile/bin/tox", line 11, in <module>
    sys.exit(cmdline())
  File "/Users/asottile/opt/venv/lib/python3.6/site-packages/tox/session.py", line 40, in main
    retcode = Session(config).runcommand()
  File "/Users/asottile/opt/venv/lib/python3.6/site-packages/tox/session.py", line 392, in runcommand
    return self.subcommand_test()
  File "/Users/asottile/opt/venv/lib/python3.6/site-packages/tox/session.py", line 567, in subcommand_test
    self.installpkg(venv, path)
  File "/Users/asottile/opt/venv/lib/python3.6/site-packages/tox/session.py", line 507, in installpkg
    venv.installpkg(path, action)
  File "/Users/asottile/opt/venv/lib/python3.6/site-packages/tox/venv.py", line 273, in installpkg
    self._install([sdistpath], extraopts=extraopts, action=action)
  File "/Users/asottile/opt/venv/lib/python3.6/site-packages/tox/venv.py", line 335, in _install
    action=action)
  File "/Users/asottile/opt/venv/lib/python3.6/site-packages/tox/venv.py", line 308, in run_install_command
    redirect=self.session.report.verbosity < 2)
  File "/Users/asottile/opt/venv/lib/python3.6/site-packages/tox/venv.py", line 414, in _pcall
    redirect=redirect, ignore_ret=ignore_ret)
  File "/Users/asottile/opt/venv/lib/python3.6/site-packages/tox/session.py", line 163, in popen
    sys.stdout.write(data)
  File "/Users/asottile/opt/venv/bin/../lib/python3.6/codecs.py", line 377, in write
    self.stream.write(data)
TypeError: write() argument must be str, not bytes

This will affect all platforms. The fix for this one is simple, patch incoming!

[asottile]

Here's a patch, I can make this into a branch later:

diff --git a/tox/session.py b/tox/session.py
index 2754787..2c62f13 100644
--- a/tox/session.py
+++ b/tox/session.py
@@ -135,7 +135,7 @@ class Action(object):
             fout.write("actionid: %s\nmsg: %s\ncmdargs: %r\n\n" % (self.id, self.msg, args))
             fout.flush()
             outpath = py.path.local(fout.name)
-            fin = outpath.open()
+            fin = outpath.open('rb')
             fin.read()  # read the header, so it won't be written to stdout
             stdout = fout
         elif returnout:
@@ -159,6 +159,9 @@ class Action(object):
             self.report.logpopen(popen, env=env)
             try:
                 if resultjson and not redirect:
+                    # we read binary from the process and must write using a
+                    # binary stream
+                    buf = getattr(sys.stdout, 'buffer', sys.stdout)
                     assert popen.stderr is None  # prevent deadlock
                     out = None
                     last_time = time.time()
@@ -168,12 +171,12 @@ class Action(object):
                         # might be no output for a long time with slow tests
                         data = fin.read(1)
                         if data:
-                            sys.stdout.write(data)
-                            if '\n' in data or (time.time() - last_time) > 1:
+                            buf.write(data)
+                            if b'\n' in data or (time.time() - last_time) > 1:
                                 # we flush on newlines or after 1 second to
                                 # provide quick enough feedback to the user
                                 # when printing a dot per test
-                                sys.stdout.flush()
+                                buf.flush()
                                 last_time = time.time()
                         elif popen.poll() is not None:
                             if popen.stdout is not None:

[fschulze]

@asottile Confirmed! This should be applied after #734 is merged to avoid conflicts. Do you want to do the PR then, or should I?

[asottile]

Yeah that was another reason I posted it as a patch because I knew it would conflict :) go for it!

[gaborbernat]

@asottile go ahead with the PR on top of master

[fschulze]

See #739
@asottile I added your name, since you did the patch.

[witsch]

Just "for the record" or in case somebody else runs into the same isse: I've adjusted a small project to use Python 3 and running tox gave me the same error message. I've reproduced the issue with a fairly small setup:

foo.py:

def bar():
    import pdb; pdb.set_trace()
    return 42

test_foo.py:

def test_bar():
    from foo import bar
    assert bar() == 42

setup.py:

from setuptools import setup, find_packages

setup(name='foo',
    version='0.1',
    packages=find_packages(),
)

tox.ini:

[tox]
envlist = py36

[testenv]
usedevelop = true
deps =
    pytest
    pdbpp
commands =
    py.test {posargs}

Running tox gave me this:

~/tox-test (master)-> tox
py36 create: /Users/zeidler/tox-test/.tox/py36
py36 installdeps: pytest, pdbpp
py36 develop-inst: /Users/zeidler/tox-test
py36 installed: attrs==17.4.0,fancycompleter==0.8,-e [email protected]:witsch/tox-test.git@298376ac293d9a4e6b210dd1cd675963a5dc7ead#egg=foo,pdbpp==0.9.2,pluggy==0.6.0,py==1.5.2,Pygments==2.2.0,pytest==3.4.0,six==1.11.0,wmctrl==0.3
py36 runtests: PYTHONHASHSEED='871445808'
py36 runtests: commands[0] | py.test
======================================= test session starts ========================================
platform darwin -- Python 3.6.3, pytest-3.4.0, py-1.5.2, pluggy-0.6.0
rootdir: /Users/zeidler/tox-test, inifile:
collected 1 item                                                                                   

test_foo.py 
>>>>>>>>>>>>>>>>>>>>>>>>>>>>> PDB set_trace (IO-capturing turned off) >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
F                                                                                [100%]

============================================= FAILURES =============================================
_____________________________________________ test_bar _____________________________________________

    def test_bar():
        from foo import bar
>       assert bar() == 42

test_foo.py:5: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
foo.py:5: in bar
    return 42
foo.py:5: in bar
    return 42
../Development/python/parts/opt/lib/python3.6/bdb.py:48: in trace_dispatch
    return self.dispatch_line(frame)
../Development/python/parts/opt/lib/python3.6/bdb.py:66: in dispatch_line
    self.user_line(frame)
../Development/python/parts/opt/lib/python3.6/pdb.py:261: in user_line
    self.interaction(frame, None)
.tox/py36/lib/python3.6/site-packages/pdb.py:243: in interaction
    self.print_stack_entry(self.stack[self.curindex])
.tox/py36/lib/python3.6/site-packages/pdb.py:800: in print_stack_entry
    print('[%d] >' % frame_index, file=self.stdout, end=' ')
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <encodings.utf_8.StreamWriter object at 0x106b70710>, object = '[31] >'

    def write(self, object):

        """ Writes the object's contents encoded to self.stream.
            """
        data, consumed = self.encode(object, self.errors)
>       self.stream.write(data)
E       TypeError: write() argument must be str, not bytes

.tox/py36/lib/python3.6/codecs.py:377: TypeError
===================================== 1 failed in 0.17 seconds =====================================
ERROR: InvocationError: '/Users/zeidler/tox-test/.tox/py36/bin/py.test'
_____________________________________________ summary ______________________________________________
ERROR:   py36: commands failed

Without the import pdb; pdb.set_trace() line things were fine. But of course at that point — i.e. after removing pretty much everything else — I already had suspect, and as it turns out, after removing pdbpp from the setup, I get my pdb prompt back… :)

Now I wonder if we could or rather should try to detect the presence of pdbpp and issue a big warning that might save some other people from spending time on this (or merely wondering if Python 3.6's pdb is broken? :))

[asottile]

@witsch that's unrelated to this issue (I imagine you'll even be able to reproduce without tox by running .tox/py36/bin/pytest)

I also can't reproduce your findings:

$ tox -e py36
py36 create: /private/tmp/wat/.tox/py36
py36 installdeps: pytest, pdbpp
py36 develop-inst: /private/tmp/wat
py36 installed: attrs==17.4.0,fancycompleter==0.8,foo==0.1,pdbpp==0.9.2,pluggy==0.6.0,py==1.5.2,Pygments==2.2.0,pytest==3.4.0,six==1.11.0,wmctrl==0.3
py36 runtests: PYTHONHASHSEED='2690305621'
py36 runtests: commands[0] | py.test
============================ test session starts ============================
platform darwin -- Python 3.6.4, pytest-3.4.0, py-1.5.2, pluggy-0.6.0
rootdir: /private/tmp/wat, inifile:
collected 1 item                                                            

test_foo.py 
>>>>>>>>>>>>>>>>>> PDB set_trace (IO-capturing turned off) >>>>>>>>>>>>>>>>>>
[31] > /private/tmp/wat/foo.py(3)bar()
-> return 42
   5 frames hidden (try 'help hidden_frames')
(Pdb++) 

[asottile]

@witsch I suspect the brokenness of your environment stems from whatever Development/python/parts/opt/lib/python3.6/pdb.py is.

[witsch]

@asottile Thanks for looking into it, and yes, it's probably unrelated to tox, which is why I put the "for the record"... It was pretty much the only hit I could find for this problem and I thought I'd put a note in case somebody runs into the same issue... 🙂

Apart from that, the strange pdb.py comes from my Python installation, which uses https://github.com/collective/buildout.python (which might also explain why @fschulze had this issue as well 🙂). In any case, I'll try again with a different Python setup. Thank you!

[fschulze]

That "strange" pdb is just the prefix where buildout.python installs, besides that it's the regular pdb from the Python source release.

I had the issue Tox on Travis, so in my case it's unrelated to buildout.python. Either it's related to the output capturing of pytest, or pdb++ does something similar and needs to be fixed.