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

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

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.

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()

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.

> 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).

> 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) ?

> 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?

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

> 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).

I've added a patch that should handle these errors (including the SysLogHandlerTest, which wasn't reported, but I think the same logic applies).

To simulate failure during setup, uncomment one or more of the lines which says

    # raise ValueError('dummy error raised')

> including the SysLogHandlerTest, which wasn't reported

Sorry, I appear to have lost the ability to read :-(

issue-29177-02.diff is a modified version of the previous patch that uses support.unlink() instead of os.remove() to handle the failure occuring for a non-existent file
when the test is skipped because of Permission denied. With this patch test_logging is ok, and test_lib2to3 runs fine after test_logging.

issue-29177-03.patch adds the following modifications to the previous patches:
  * Catch only OSError: it is better not to catch programming errors as they may go unnoticed when the test is skipped.
  * Report the OSError in the skip message.
  * Reduce the scope of the try clause to just the code that uses system calls.
  * The cleanup done in setUp() by the previous patch in the except clause does not seem to be needed as the tearDown() method is invoked when the test is skipped.

Thanks for the improvements to my patch. The 03-version looks good to me.

New changeset 6bf563472ccd by Vinay Sajip in branch '3.6':
Fixes #29177: Improved resilience of logging tests which use socket servers.
https://hg.python.org/cpython/rev/6bf563472ccd

New changeset 3f324d5df0c0 by Vinay Sajip in branch 'default':
Closes #29177: Merged fix from 3.6.
https://hg.python.org/cpython/rev/3f324d5df0c0

nosy: + python-dev
messages: + msg285053

resolution: fixed
stage: patch review -> resolved

messages: + msg284919

assignee: vinay.sajip
keywords: + patch
stage: needs patch -> patch review