classification
Title: skip tests of test_logging when bind() raises PermissionError (non-root user on Android)
Type: behavior Stage: resolved
Components: Tests Versions: Python 3.7, Python 3.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: python-dev, vinay.sajip, xdegaye
Priority: normal Keywords: patch

Created on 2017-01-06 11:14 by xdegaye, last changed 2017-01-09 16:55 by python-dev. This issue is now closed.

Files
File name Uploaded Description Edit
issue-29177-01.diff vinay.sajip, 2017-01-06 21:41 Initial patch for this issue - against the 3.6 branch. review
issue-29177-02.diff xdegaye, 2017-01-07 15:07 review
issue-29177-03.patch xdegaye, 2017-01-07 15:07 review
Messages (14)
msg284812 - (view) Author: Xavier de Gaye (xdegaye) * (Python committer) Date: 2017-01-06 11:14
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
msg284815 - (view) Author: Xavier de Gaye (xdegaye) * (Python committer) Date: 2017-01-06 12:05
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.
msg284826 - (view) Author: Xavier de Gaye (xdegaye) * (Python committer) Date: 2017-01-06 15:42
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()
msg284827 - (view) Author: Xavier de Gaye (xdegaye) * (Python committer) Date: 2017-01-06 15:48
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.
msg284828 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-01-06 16:07
> 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).
msg284831 - (view) Author: Xavier de Gaye (xdegaye) * (Python committer) Date: 2017-01-06 16:19
> 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) ?
msg284841 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-01-06 17:54
> 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?
msg284846 - (view) Author: Xavier de Gaye (xdegaye) * (Python committer) Date: 2017-01-06 19:53
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.
msg284847 - (view) Author: Xavier de Gaye (xdegaye) * (Python committer) Date: 2017-01-06 20:03
> 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).
msg284857 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-01-06 21:41
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')
msg284862 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-01-06 22:13
> including the SysLogHandlerTest, which wasn't reported

Sorry, I appear to have lost the ability to read :-(
msg284919 - (view) Author: Xavier de Gaye (xdegaye) * (Python committer) Date: 2017-01-07 15:07
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.
msg284941 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2017-01-07 22:00
Thanks for the improvements to my patch. The 03-version looks good to me.
msg285053 - (view) Author: Roundup Robot (python-dev) Date: 2017-01-09 16:55
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
History
Date User Action Args
2017-01-09 16:55:38python-devsetstatus: open -> closed

nosy: + python-dev
messages: + msg285053

resolution: fixed
stage: patch review -> resolved
2017-01-07 22:00:41vinay.sajipsetmessages: + msg284941
2017-01-07 15:07:32xdegayesetfiles: + issue-29177-03.patch
2017-01-07 15:07:16xdegayesetfiles: + issue-29177-02.diff

messages: + msg284919
2017-01-06 22:13:45vinay.sajipsetmessages: + msg284862
2017-01-06 21:41:12vinay.sajipsetfiles: + issue-29177-01.diff
messages: + msg284857

assignee: vinay.sajip
keywords: + patch
stage: needs patch -> patch review
2017-01-06 21:30:19xdegayelinkissue26865 dependencies
2017-01-06 20:03:39xdegayesetmessages: + msg284847
2017-01-06 19:53:57xdegayesetassignee: xdegaye -> (no value)
messages: + msg284846
title: skip tests using socketserver.UnixStreamServer when bind() raises PermissionError -> skip tests of test_logging when bind() raises PermissionError (non-root user on Android)
2017-01-06 17:54:55vinay.sajipsetmessages: + msg284841
2017-01-06 16:19:52xdegayesetmessages: + msg284831
2017-01-06 16:07:02vinay.sajipsetmessages: + msg284828
2017-01-06 15:48:52xdegayesetmessages: + msg284827
2017-01-06 15:42:02xdegayesetmessages: + msg284826
2017-01-06 12:05:18xdegayesetnosy: + vinay.sajip
messages: + msg284815
2017-01-06 11:14:22xdegayecreate