Bug 13257

After applying this patch to ptest-runner:
https://lists.yoctoproject.org/pipermail/yocto/2019-April/044725.html

the timeout issue that still remains is that httplib test of python3 takes more than 5 minutes to execute (5 minutes is ptest-runner's default that we probably should increase):
0:06:39 load avg: 0.76 [177/416/1] test_http_cookies
0:06:39 load avg: 0.76 [178/416/1] test_httplib

ERROR: Exit status is 9
DURATION: 701
TIMEOUT: /usr/lib/python3/ptest
END: /usr/lib/python3/ptest
2019-04-04T16:40
STOP: /home/root/ptest-runner

It seems that httplib is genuinely stuck. With additional verbosity it stops here:

PASS: test_readinto_head (test.test_httplib.BasicTest)
PASS: test_readline_bound_content_length (test.test_httplib.BasicTest)
PASS: test_readlines_content_length (test.test_httplib.BasicTest)

After a bit of bisecting, I can confirm that this commit is introducing the issue :(

a7ba3a7a3e134fd9bfd5c700c2f34edcdf3a689b is the first bad commit
commit a7ba3a7a3e134fd9bfd5c700c2f34edcdf3a689b
Author: Bruce Ashfield <bruce.ashfield@gmail.com>
Date:   Tue Mar 5 21:26:45 2019 -0500

    poky/kernel: make default 5.0
    
    (From meta-yocto rev: a1b111f742ac781cf35769e52cac29125569cb9b)
    
    Signed-off-by: Bruce Ashfield <bruce.ashfield@gmail.com>
    Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>


How to reproduce:

root@qemux86-64:~# python3 -m test test_httplib
Run tests sequentially
0:00:00 load avg: 0.00 [1/1] test_httplib

(blocks forever here, in roughly 9 attempts out of 10)

^CWarning -- threading._dangling was modified by test_httplib
  Before: <_weakrefset.WeakSet object at 0x7f44a1a8a8d0>
  After:  <_weakrefset.WeakSet object at 0x7f44a1a8a6a0> 

== Tests result: INTERRUPTED ==

Test suite interrupted by signal SIGINT.
1 test omitted:
    test_httplib

Total duration: 926 ms
Tests result: INTERRUPTED
^CException ignored in: <module 'threading' from '/usr/lib/python3.7/threading.py'>
Traceback (most recent call last):
  File "/usr/lib/python3.7/threading.py", line 1273, in _shutdown
    t.join()
  File "/usr/lib/python3.7/threading.py", line 1032, in join
    self._wait_for_tstate_lock()
  File "/usr/lib/python3.7/threading.py", line 1048, in _wait_for_tstate_lock
    elif lock.acquire(block, timeout):
KeyboardInterrupt

The specific issue with the unit test is that it's closing a socket connection, but it has no effect: netstat still shows the connection as ESTABLISHED on 5.0 kernel.

root@qemux86-64:~# python3 -m test test_httplib -v
== CPython 3.7.2 (default, Apr 5 2019, 15:17:15) [GCC 8.3.0]
== Linux-5.0.0-yocto-standard-x86_64-with-glibc2.2.5 little-endian
== cwd: /var/volatile/tmp/test_python_288
== CPU count: 1
== encodings: locale=UTF-8, FS=utf-8
...
test_response_fileno (test.test_httplib.BasicTest) ... 

^^^^ blocks forever.

On 4.18 kernel:

root@qemux86-64:~# python3 -m test test_httplib -v
== CPython 3.7.2 (default, Apr 5 2019, 15:17:15) [GCC 8.3.0]
== Linux-4.18.27-yocto-standard-x86_64-with-glibc2.2.5 little-endian
== cwd: /var/volatile/tmp/test_python_309
== CPU count: 1
== encodings: locale=UTF-8, FS=utf-8
....
test_response_fileno (test.test_httplib.BasicTest) ... ok
....

I couldn't reproduce this with 4.19, I could with 5.0. I tried reverting https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=3c82a21f4320c8d54cf6456b27c8d49e5ffb722e and I think that stopped the hangs. I'd need more test runs to be 100% sure. Adding Bruce to cc.

Having mentioned the commit, it all started working. Will look into it more tomorrow

Can't get it to fail at all now! :(

For me, the failures weren’t 100%, more like 9 out of 10.

Found a more reliable way to brute force reproduce it:

meta/lib/oeqa/runtime/cases/python.py:

+    def test_python3_httplib(self):
+        for _ in range(50):
+            cmd = "python3 -m test test_httplib -v"
+            status, output = self.target.run(cmd)
+            msg = 'Exit status was not 0. Output: %s' % output
+            self.assertEqual(status, 0, msg=msg)


Confirmed that reverting the commit I mentioned doesn't fix it. Also confirmed its not fixed by v5.0.7

v4.20.17 doesn't have the issue
v5.1-rc3 does
v5.0-rc3 does
v5.0-rc1 does

Bisect suggests the commit which introduces the problem is:

commit 4f693b55c3d2d2239b8a0094b518a1e533cf75d5 (HEAD, refs/bisect/bad)
Author: Eric Dumazet <edumazet@google.com>
Date:   Tue Nov 27 14:42:03 2018 -0800

    tcp: implement coalescing on backlog queue
    
    In case GRO is not as efficient as it should be or disabled,
    we might have a user thread trapped in __release_sock() while
    softirq handler flood packets up to the point we have to drop.
    
    This patch balances work done from user thread and softirq,
    to give more chances to __release_sock() to complete its work
    before new packets are added the the backlog.
    
    This also helps if we receive many ACK packets, since GRO
    does not aggregate them.
    
    This patch brings ~60% throughput increase on a receiver
    without GRO, but the spectacular gain is really on
    1000x release_sock() latency reduction I have measured.
    
    Signed-off-by: Eric Dumazet <edumazet@google.com>
    Cc: Neal Cardwell <ncardwell@google.com>
    Cc: Yuchung Cheng <ycheng@google.com>
    Acked-by: Neal Cardwell <ncardwell@google.com>
    Signed-off-by: David S. Miller <davem@davemloft.net>

I've asked for advice https://lore.kernel.org/netdev/85aabf9d4f41b6c57629e736993233f80a037e59.camel@linuxfoundation.org/T/#u

I can't say that I understand why that is triggering the hang completely either, but is clearly mucking in the right part of the kernel to be the suspect commit.

I'm following your upstream question as well.

We can of course easily revert that commit in the linux-yocto 5.x branches, but as we all know, this really doesn't look oe/yocto/test specific, so getting a root cause from -netdev would be ideal, since this will just be waiting for us on all future kernel versions.

Root caused, worked around in python3, fixed in the kernel, and work around removed.  All sorted as of 21bfbef23e1f4c90070017e19f70e488e6ff64be.