skip tests of test_logging when bind() raises PermissionError (non-root user on Android)

[xdegaye]

BPO	29177
Nosy	@vsajip, @xdegaye
Files	issue-29177-01.diff: Initial patch for this issue - against the 3.6 branch. issue-29177-02.diff issue-29177-03.patch

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = 'https://github.com/vsajip'
closed_at = <Date 2017-01-09.16:55:38.170>
created_at = <Date 2017-01-06.11:14:22.227>
labels = ['3.7', 'type-bug', 'tests']
title = 'skip tests of test_logging when bind() raises PermissionError (non-root user on Android)'
updated_at = <Date 2017-01-09.16:55:38.168>
user = 'https://github.com/xdegaye'

bugs.python.org fields:

activity = <Date 2017-01-09.16:55:38.168>
actor = 'python-dev'
assignee = 'vinay.sajip'
closed = True
closed_date = <Date 2017-01-09.16:55:38.170>
closer = 'python-dev'
components = ['Tests']
creation = <Date 2017-01-06.11:14:22.227>
creator = 'xdegaye'
dependencies = []
files = ['46180', '46193', '46194']
hgrepos = []
issue_num = 29177
keywords = ['patch']
message_count = 14.0
messages = ['284812', '284815', '284826', '284827', '284828', '284831', '284841', '284846', '284847', '284857', '284862', '284919', '284941', '285053']
nosy_count = 3.0
nosy_names = ['vinay.sajip', 'xdegaye', 'python-dev']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue29177'
versions = ['Python 3.6', 'Python 3.7']

[xdegaye]

This happens on Android for a non-root user. One test in test_logging fails. Multiple tests fail in test_socketserver with identical backtraces, only the first one is listed here.

====================================================================== [1955/2616]
ERROR: test_noserver (test.test_logging.UnixSocketHandlerTest)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/test/test_logging.py", line 1527, in setUp
    SocketHandlerTest.setUp(self)
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/test/test_logging.py", line 1444, in setUp
    self.handle_socket, 0.01)
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/test/test_logging.py", line 885, in __init__
    bind_and_activate)
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/socketserver.py", line 452, in __init__
    self.server_bind()
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/test/test_logging.py", line 889, in server_bind
    super(TestTCPServer, self).server_bind()
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/socketserver.py", line 466, in server_bind
    self.socket.bind(self.server_address)
PermissionError: [Errno 13] Permission denied

====================================================================== [905/2616]
ERROR: test_ForkingUnixDatagramServer (test.test_socketserver.SocketServerTest)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/test/test_socketserver.py", line 243, in test_Fork
ingUnixDatagramServer
    self.dgram_examine)
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/test/support/__init__.py", line 2040, in decorator
    return func(*args)
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/test/test_socketserver.py", line 121, in run_serve
r
    svrcls, hdlrbase)
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/test/test_socketserver.py", line 114, in make_serv
er
    server = MyServer(addr, MyHandler)
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/socketserver.py", line 452, in __init__
    self.server_bind()
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/socketserver.py", line 466, in server_bind
    self.socket.bind(self.server_address)
PermissionError: [Errno 13] Permission denied

[xdegaye]

test_logging fails also with the following backtrace:

======================================================================
FAIL: test_output (test.test_logging.UnixSocketHandlerTest)
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/test/test_logging.py", line 1527, in setUp
    SocketHandlerTest.setUp(self)
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/test/test_logging.py", line 1442, in setUp
    BaseTest.setUp(self)
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/test/test_logging.py", line 111, in setUp
    raise AssertionError('Unexpected handlers: %s' % hlist)
AssertionError: Unexpected handlers: [<StreamHandler (NOTSET)>]

This is because when a test fails or when it is skipped, the BaseTest.tearDown() method is not called and as a consequence the following test fails.

[xdegaye]

To reproduce the test_logging cleanup problem, insert skipTest() in setUp():

diff -r 4a97fa319bf7 Lib/test/test_logging.py
--- a/Lib/test/test_logging.py  Fri Jan 06 09:52:19 2017 +0100
+++ b/Lib/test/test_logging.py  Fri Jan 06 16:39:38 2017 +0100
@@ -1440,6 +1440,7 @@
         """Set up a TCP server to receive log messages, and a SocketHandler
         pointing to that server's address and port."""
         BaseTest.setUp(self)
+        self.skipTest('Skip test in setUp().')
         self.server = server = self.server_class(self.address,
                                                  self.handle_socket, 0.01)
         server.start()

[xdegaye]

The test_logging cleanup problem induces another problem. When test_lib2to3 is run after the failing test_logging then test_lib2to3 fails with:

======================================================================
FAIL: test_filename_changing_on_output_single_dir (lib2to3.tests.test_main.TestMain)
2to3 a single directory with a new output dir and suffix.
----------------------------------------------------------------------

Traceback (most recent call last):
  File "/sdcard/org.bitbucket.pyona/lib/python3.7/lib2to3/tests/test_main.py", line 91, in test_file
name_changing_on_output_single_dir
    self.py3_dest_dir, self.py2_src_dir), stderr)
AssertionError: "Output in '/data/local/tmp/tmp4eyn96tg/python3_project' will mirror the input direc
tory '/data/local/tmp/tmp4eyn96tg/python2_project' layout" not found in 'WARNING: --write-unchanged-
files/-W implies -w.\n'

---

Ran 616 tests in 140.986s

FAILED (failures=1, expected failures=1)
Warning -- logging._handlerList was modified by test_lib2to3
test test_lib2to3 failed

It seems that this is related to the test_logging failure because the expected string "Output in '/data/local/tmp/tmp4eyn96tg/python3_project' will mirror the input directory '/data/local/tmp/tmp4eyn96tg/python2_project' layout" is output by logger.info() in Lib/lib2to3/main.py:243.

[vsajip]

To reproduce the test_logging cleanup problem, insert skipTest() in setUp()

My understanding is that skipTest would normally be raised in the test method itself or as a decorator to it, and not in setUp() itself. (It wouldn't make sense to, as that would skip every test in the test case - not the obvious thing to do.) I can understand that failures that happen in setUp() may cause tearDown() not to be called.

I would guess that setUp() should recover from any problem and set a flag which is then used to skip in the other tests (which rely on that problem not being there).

[xdegaye]

My understanding is that skipTest would normally be raised in the test method itself or as a decorator to it, and not in setUp() itself.

Agreed. Would that make sense to move the server.start() part out of setUp() and in its own method that would be called by each test (I am not very familiar with test_logging) ?

[vsajip]

Would that make sense to move the server.start() part out of setUp() and in its own method

My preference would be to just catch the error in SocketHandlerTest.setUp() and leave things in a tidy state (e.g. .server and .sock_hdlr set to None), make the tearDown() logic take that into account, and in each test just skip if .server is None.

Do you want to take this on, or do you want me to look at it?

[xdegaye]

I have split this issue, bpo-29184 is for fixing the tests on test_socketserver and this issue is for fixing the tests on test_logging.

[xdegaye]

Do you want to take this on, or do you want me to look at it?

I would be very grateful if you would handle that :)
But if you cannot spare the time, I can give it a try.
One point I forgot to mention is that DatagramHandlerTest and SysLogHandlerTest also fail with PermissionError when run as their subclass UnixDatagramHandlerTest (resp. UnixSysLogHandlerTest).