New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Overhaul test suite to be compatible with pytest #1100

Closed
bitprophet opened this Issue Oct 23, 2017 · 23 comments

Comments

Projects
None yet
1 participant
@bitprophet
Member

bitprophet commented Oct 23, 2017

Been kinda unhappy with Paramiko's handrolled semi-unittest-based test.py since I came on board, and ideally I'd like to end up using my rspec-esque test kit, but since the latter has been rewritten under pytest, just getting our suite working with pytest would be a great step forwards. Plus all the other reasons to do so: pytest is the leading test runner these days, many folks are familiar with it, lots of plugins to use, better tox integration for people who use that (not me, yet), etc.

I am working on this right now as a prerequisite for a bunch of test-driven thorny auth crap (#387) so the ticket is just my usual keeping track of stuff for posterity.

@bitprophet bitprophet added the Support label Oct 23, 2017

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 23, 2017

The first big thing that jumps out at me is that pytest is real mad at all the GSSAPI related tests, partly due to the tricks they use to be CLI-configurable (the GSSAPI feature owners test against real Kerberos installs, IIRC.)

That leads us to two things:

  • Those tests are skipped unless explicitly enabled, so that needs to be reinstated in pytest terms
  • The configurability will also need to be redone. it's not clear to me how pytest "wants" to handle this, I trolled the docs a bit but didn't find anything besides stuff for setting pytest's own default CLI args. Worst case I figure we just use os.environ as that's not the worst pattern ever.
    • I may punt on this myself, given I can't actually make these tests pass anyways, so the feature owners would need to put work into that next time they touch things.
@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 23, 2017

Also finding this skipUnlessBuiltin('buffer'/'memoryview') stuff added this past spring; now that we've dropped Python 2.6, we can at least always assume memoryview exists, though since buffer seems to remain Python 2 only, we'll need to keep skipUnlessBuiltin('buffer') around in some form for Python 3.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 23, 2017

Also, the current impl of skipUnlessBuiltin does getattr(builtins, name, None) is None and I don't see why; using hasattr seems to work fine for me under both interpreter families?

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 23, 2017

All these nasty ugly globals in here 😭

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 23, 2017

Doing my best not to get sidetracked by overall modernization, but just enough to get pytest working. E.g. not going nuts with more old string interpolation fixes; not immediately replacing the current nasty logic around SFTP tests' temporary folders; etc. That stuff will remain 'old' for now.

However a lot needs doing anyway, e.g. pytest fixtures (for things like the SFTP client setup, which I think does fall beyond the pale & should be taken care of now) don't seem to work with explicitly-unittest-subclased test suites, but then that forces my hand re: s/self.assertEquals(x,y)/assert x == y/ since the objects no longer have assertEquals.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 23, 2017

Also, to my chagrin, trying not to refactor all the obvious copypasta in here 🤦‍♂️

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 23, 2017

Note to self: running 'big-sftp' test module by itself on master takes ~17s, and ~18s under pytest, so I'm not actually sure the global nonsense was even for saving time (I forget how raw unittest internals work but perhaps it's resetting or reimporting things on each test?)

When I slap a scope='session' onto the new fixture in pytest, we save a handful of seconds - it now takes ~14-15s instead of ~18s. Think it's probably worthwhile for now? Easily revertable if it seems to cause problems.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 23, 2017

Grump, either approach is insufficient, once I turn to the main SFTP suite – in part because lots of tests explicitly redefine the value of the global sftp to 'reset' it (either to 'fix' state they changed, like closing it, or simply to prove that the connection can be reopened) -- which obviously doesn't mesh with the more deterministic style of "not fucking using globals."

Gonna have to dig a bit more here. Hooray.

@bitprophet bitprophet referenced this issue Oct 23, 2017

Open

Second-wave test suite cruft cleanup #1101

0 of 7 tasks complete
@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 24, 2017

Having intermittent hangs that seem like they only pop up in the SFTP suite, though they are much easier to trigger if they run as part of the main overall suite. Love this stuff, really gets me excited and definitely not at all frustrating or sapping my will to live 👍

The SFTP suite does pass 100% now so I think I am just gonna go run each other module by itself (another nice benefit of moving to pytest; previously one had to add boilerplate to a given test file to run it alone) and try to get everything else to where it can pass. Then we can worry about hangs and shit.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 24, 2017

Also, skipped tests (mostly gssapi ones) seem to emit a big gnarly path that has nothing to do with the actual test being skipped. Swell. At least it's just ugly.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 24, 2017

Rest of test modules appear to pass without modification, so, that's nice. Means I can defer updating them away from unittest-style, apparently, too? pytest doesn't seem to care if your suite mixes and matches discovery styles.

So this leaves the SFTP module hangs as the main outstanding issue. Seems like test_4_prefetch_seek is a frequent culprit, though it's far from the only spot the hang appears.

Of note - using pytest-timeout with mild success here, in its thread incarnation as the signal one does not suffice. Probably gonna add it for reals since the thread dumps are occasionally useful & it means we can axe tests after, say, 10s instead of a Travis 10min wait.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 24, 2017

Seems the hangs are more likely to occur on Python 3, not too surprising, it's always been a bigger culprit when it comes to race condition type stuff. Honestly probably useful here, means I can run under 3 locally and have a better chance at repro'ing (tho it comes up pretty often under 2 too)

Seems like the issue happens about as often regardless of whether the 'server' side of the fixture is scoped to session or not. I guess that's a good thing.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 24, 2017

Using an error-counter task and running just one test (test_4_prefetch_seek as above) I can go 100 iterations w/o error, implying there's still some state bleed/cruft issues despite not using session-level fixtures. Conversely, running the two SFTP suites (but no others, yet) has so far resulted in an error on the 1st run a handful of times in a row.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 24, 2017

Digging into things more now. Quick sanity check: why the hell was pytest-timeout showing SO many threads (like...at least a dozen or two) when I only expect a handful to be in flight during any given test? Is that a potential sign of the state that is gumming things up, or do I just not fully understand what's going on?

When I run a single big-sftp test on its lonesome and emit threading.enumerate() I see what I expected - two Transport threads (server and client), the main server thread, and the process-main thread. 4 threads.

When I run more tests (e.g. both SFTP suites), by the time we get to the test I decorated (which is maybe a dozen tests in) there are dozens of threads. (and if I Ctrl-C, only then do I see all the debug logging about hitting EOF and shutting down - for basically all those threads.)

So sure, there's a shutdown problem, but still doesn't explain why any of these threads are affecting any of the others (if that's even what is going on.) More digging.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 24, 2017

Weirdly, when I re-enable pytest-timeout (I had it off for a bit to make sure it was not confusing things) it shows the main thread hanging out in a long return chain from a network read - in a spot that shouldn't have actually been blocking on anything (being outside any of the lock-obtaining bits.)

Digging more into it to make sure my timeout isn't too low (it was in a test that does e.g. 1024 reads in a loop) cuz I don't entirely get why the main thread would stop there instead of in a spot where it's waiting on one of the other threads. (Hm - maybe it's because there are enough other threads active that the main thread's just getting choked out by the GIL? Would explain why the issue never comes up in a single-test setup...?)


With a 30s timeout the issue is harder to repro now - I don't seem to have written it down above but I remember setting it to 30s at one point and finding the issue still popping up. Maybe that was w/ the full suite and not just the sftp ones? (If I'm right about this being "caused" by just too many active threads, that would make sense...)

Yea...even running the full suite a few times in a row, a 30s timeout isn't triggering any fails. Dropping it back down to 10s almost immediately times out. Implies that there really is no hang going on, just lots-o-threads slowing things way down (and no doubt exacerbated by pytest-timeout when it is in play.)

So then the question is, was this happening under raw unittest with the old suite? I needed to do more comparisons anyway to make sure this switcheroo didn't lose any tests or massively inflate runtime...

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 24, 2017

Hm seems too early to make that call, eg Travis running my latest HEAD is definitely still getting full-on 10 minute (MINUTE, not second) long hangs and erroring out. And that's with no pytest-timeout in play at all (I backed it out of git because I realized that using its thread backend, as we apparently must do, is not really worth the cost.)

Only difference ought to be A) Linux vs Mac and B) I still haven't committed the rollback of scope='session' on the SFTP test server (as I wasn't yet positive about whether it helps or hurts.)

Definitely having issues repro'ing now, even under Python 3, locally. EDIT: yea, when I go back to scoping that fixture to 'session' level (locally), repro happens again basically every time (at 10s timeout, and also at 30s timeout, again multiple times.)


Partial stack of one spot where the main thread was at a (30s) timeout cutoff:

File "/Users/jforcier/Code/oss/paramiko/tests/loop.py", line 54, in send
  self.__mate.__feed(data)
File "/Users/jforcier/Code/oss/paramiko/tests/loop.py", line 84, in __feed
  self.__cv.notifyAll()
File "/usr/local/var/pyenv/versions/3.5.2/lib/python3.5/threading.py", line 362, in notify_all
  self.notify(len(self._waiters))
File "/usr/local/var/pyenv/versions/3.5.2/lib/python3.5/threading.py", line 345, in notify
  waiters_to_notify = _deque(_islice(all_waiters, n))
File "/Users/jforcier/Code/oss/paramiko/paramiko/channel.py", line 130, in __del__
  self.close()
File "/Users/jforcier/Code/oss/paramiko/paramiko/channel.py", line 655, in close
  self.transport._send_user_message(m)
File "/Users/jforcier/Code/oss/paramiko/paramiko/transport.py", line 1720, in _send_user_message
  self.clear_to_send_lock.acquire()

I've seen it hang here a few times now, too (though it's not always here.)

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 24, 2017

Got up to 47 full test suite iterations under Python 30s timeout w/ pytest-timeout, no timeouts. Travis also ran that commit no problem, tho I am gonna hit its 'rerun' button a few times too. Real bizarre but I'll take it. Still gotta do that comparison to master tho.

EDIT: also, on Travis, up to at least 10x full cycles (so, the whole matrix) w/o any timeouts.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 24, 2017

Old suite, under Python 3.5, locally, with coverage enabled (w/o coverage saves maybe 2s but that feels within stdev): Ran 211 tests in 18.630s
On Travis (the 3.5 cell): Ran 211 tests in 34.615s

New suite, 3.5, locally: 203 passed, 14 skipped in 57.67 seconds
On Travis: 203 passed, 14 skipped in 80.35 seconds

So that's disappointing. For now I assume it's due to the creation of a new test server for every test; the old setup (as noted way above) was presumably keeping it around for the whole test run?

Also the stats line implies pytest is actually running an additional 6 or so tests, which is mildly amusing (its discovery is definitely more thorough than the old setup's was, which was basically explicit opt-in.)

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 24, 2017

OK, the extras seem to be the GSSAPI tests - right - makes sense, the old test.py wouldn't even load those up. So we're good I think, except for the tests now being a lot slower :(

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 25, 2017

Double checked that today, enabling session-scoped SFTP stub server is still the trigger for hangs, so at least that's consistent...>_>

Using pytest's builtin timing stuff to examine slowness. By default (no session-scoped server), it looks like this (I arbitrarily cut off after 1 page of my terminal):

10.68s call     tests/test_sftp_big.py::TestBigSFTP::test_2_big_file                                 
5.08s call     tests/test_auth.py::AuthTest::test_9_auth_non_responsive                              
5.03s call     tests/test_client.py::SSHClientTest::test_9_auth_timeout                              
4.85s call     tests/test_sftp_big.py::TestBigSFTP::test_1_lots_of_files                             
2.64s call     tests/test_sftp_big.py::TestBigSFTP::test_5_readv_seek                                
2.21s call     tests/test_transport.py::TransportTest::test_5_keepalive                              
1.34s call     tests/test_sftp_big.py::TestBigSFTP::test_6_lots_of_prefetching                       
1.32s setup    tests/test_sftp.py::TestSFTP::test_K_utf8                                             
1.32s setup    tests/test_sftp.py::TestSFTP::test_8_setstat                                          
1.31s setup    tests/test_sftp.py::TestSFTP::test_2_sftp_can_be_used_as_context_manager              
1.28s setup    tests/test_sftp.py::TestSFTP::test_F_mkdir                                            
1.26s setup    tests/test_sftp.py::TestSFTP::test_L_utf8_chdir                                       
1.25s setup    tests/test_sftp.py::TestSFTP::test_N_put_without_confirm                              
1.25s setup    tests/test_sftp.py::TestSFTP::test_2_close                                            
1.24s setup    tests/test_sftp.py::TestSFTP::test_5_rename                                           
1.23s setup    tests/test_sftp.py::TestSFTP::test_6_folder                                           
1.23s setup    tests/test_sftp.py::TestSFTP::test_3_write                                            
1.23s setup    tests/test_sftp.py::TestSFTP::test_3_sftp_file_can_be_used_as_context_manager         
1.22s setup    tests/test_sftp.py::TestSFTP::test_E_realpath                                         
1.22s setup    tests/test_sftp.py::TestSFTP::test_B_write_seek                                       
1.22s setup    tests/test_sftp.py::TestSFTP::test_7_5_listdir_iter                                   
1.21s setup    tests/test_sftp.py::TestSFTP::test_7_listdir                                          
1.19s setup    tests/test_sftp.py::TestSFTP::test_G_chdir                                            
1.19s setup    tests/test_sftp.py::TestSFTP::test_sftp_attributes_empty_str                          
1.19s setup    tests/test_sftp.py::TestSFTP::test_H_get_put                                          
1.19s setup    tests/test_sftp.py::TestSFTP::test_O_getcwd                                           
1.19s setup    tests/test_sftp_big.py::TestBigSFTP::test_3_big_file_pipelined                        
1.18s setup    tests/test_sftp.py::TestSFTP::test_D_flush_seek                                       
1.18s setup    tests/test_sftp.py::TestSFTP::test_M_bad_readv                                        
1.18s setup    tests/test_sftp.py::TestSFTP::test_1_file                                             
1.18s setup    tests/test_sftp.py::TestSFTP::test_J_x_flag                                           
1.18s setup    tests/test_sftp_big.py::TestBigSFTP::test_7_prefetch_readv                            
1.17s setup    tests/test_sftp_big.py::TestBigSFTP::test_2_big_file                                  
1.17s setup    tests/test_sftp.py::TestSFTP::test_A_readline_seek                                    
1.16s setup    tests/test_sftp_big.py::TestBigSFTP::test_A_big_file_renegotiate                      
1.16s setup    tests/test_sftp_big.py::TestBigSFTP::test_9_big_file_big_buffer                       
1.15s setup    tests/test_sftp.py::TestSFTP::test_putfo_empty_file                                   
1.15s setup    tests/test_sftp.py::TestSFTP::test_5a_posix_rename                                    
1.15s setup    tests/test_sftp_big.py::TestBigSFTP::test_8_large_readv                               
1.14s setup    tests/test_sftp_big.py::TestBigSFTP::test_6_lots_of_prefetching                       
1.14s setup    tests/test_sftp.py::TestSFTP::test_I_check                                            
1.13s setup    tests/test_sftp.py::TestSFTP::test_9_fsetstat                                         
1.13s setup    tests/test_sftp.py::TestSFTP::test_write_buffer                                       
1.13s setup    tests/test_sftp_big.py::TestBigSFTP::test_5_readv_seek                                
1.12s setup    tests/test_sftp.py::TestSFTP::test_C_symlink                                          
1.11s setup    tests/test_sftp.py::TestSFTP::test_O_non_utf8_data                                    
1.11s call     tests/test_sftp_big.py::TestBigSFTP::test_4_prefetch_seek                             
1.09s call     tests/test_transport.py::TransportTest::test_L_handshake_timeout                      
1.09s setup    tests/test_sftp_big.py::TestBigSFTP::test_4_prefetch_seek                             
1.08s setup    tests/test_sftp_big.py::TestBigSFTP::test_1_lots_of_files                             
1.08s setup    tests/test_sftp.py::TestSFTP::test_write_memoryview                                   
1.07s setup    tests/test_sftp.py::TestSFTP::test_4_append                                           
1.05s call     tests/test_sftp_big.py::TestBigSFTP::test_3_big_file_pipelined                        
0.79s call     tests/test_transport.py::TransportTest::test_I_rekey_deadlock                         
0.78s call     tests/test_sftp_big.py::TestBigSFTP::test_7_prefetch_readv                            
0.75s call     tests/test_transport.py::TransportTest::test_H_send_ready                             
0.67s call     tests/test_sftp_big.py::TestBigSFTP::test_8_large_readv                               
0.57s call     tests/test_sftp_big.py::TestBigSFTP::test_A_big_file_renegotiate                      
0.54s call     tests/test_buffered_pipe.py::BufferedPipeTest::test_2_delay                           
0.53s call     tests/test_transport.py::TransportTest::test_A_select                                 
0.52s call     tests/test_client.py::SSHClientTest::test_7_banner_timeout                            
0.48s call     tests/test_client.py::SSHClientTest::test_6_cleanup                                   
0.35s call     tests/test_transport.py::TransportTest::test_B_renegotiate                            
0.33s call     tests/test_transport.py::TransportTest::test_G_stderr_select                          
0.32s call     tests/test_sftp_big.py::TestBigSFTP::test_9_big_file_big_buffer                       
0.30s call     tests/test_transport.py::TransportTest::test_F_port_forwarding                        
0.29s call     tests/test_transport.py::TransportTest::test_channel_send_misc                        
0.29s call     tests/test_transport.py::TransportTest::test_4_special                                
0.29s call     tests/test_transport.py::TransportTest::test_E_reverse_port_forwarding                
0.28s call     tests/test_transport.py::TransportTest::test_9_exit_status                            
0.24s call     tests/test_transport.py::TransportTest::test_6a_channel_can_be_used_as_context_manager
0.24s call     tests/test_client.py::SSHClientTest::test_host_key_negotiation_2                      
0.24s call     tests/test_transport.py::TransportTest::test_channel_send_buffer                      
0.24s call     tests/test_client.py::SSHClientTest::test_3_multiple_key_files                        
0.23s call     tests/test_transport.py::TransportTest::test_channel_send_memoryview                  
0.23s call     tests/test_sftp.py::TestSFTP::test_G_chdir                                            
0.23s call     tests/test_transport.py::TransportTest::test_6_exec_command                           
0.23s call     tests/test_transport.py::TransportTest::test_8_channel_exception                      
0.22s call     tests/test_transport.py::TransportTest::test_M_select_after_close                     
0.22s call     tests/test_buffered_pipe.py::BufferedPipeTest::test_3_close_while_reading             
0.22s call     tests/test_auth.py::AuthTest::test_3_multipart_auth                                   

So, SFTP being slow is no big surprise (makes me think it might be nice to truly stub it out so it does not touch disk...but that can be later) but I note many of the ~1-1.5s bits are in the setup for SFTP tests and not the actual execution.

Hoping the timeout plugin lets me actually just treat timeouts as failures (prior to now I always ran with -x to fail-fast) so I can get some actual timings on the session-scoped thing - I suspect that will remove that setup time for the SFTP tests.

Also curious how the suite looks when I filter out the SFTP tests entirely on both branches - how much of the slow is pytest and how much is in this SFTP crap?

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 25, 2017

Grump, yea, the thread timeout backend does kill the entire process (as documented) and the default signal one still isn't working for me (the deadlocks are strong & ignore even manual Ctrl-C; have to Ctrl-Z and kill every time - so it's no surprise that other signal approaches also fail to interrupt.) And the timing stuff only prints at the end, which is frustrating, I'd prefer it to print as we go.

Slapped debuggery into the right pytest hooks to print duration capture as-we-go and as I suspected, with session-scoped stub server, the ~1.25s setup time cost only occurs on the 1st SFTP test and the rest are negligible (0.0Ns).


If we assume we mark SFTP tests as being integration/slow tests and only run them on CI - how does this look? (I'm just using -k 'not sftp' for now, to skip any test with 'sftp' in its node/path.)

  • There are 44 SFTP tests; when run by their lonesome, the test run takes 80s (implying that these are the bulk of the runtime, unsurprisingly).
  • The 163 (unskipped) non-SFTP tests take about 25s to run. Still shitty, but.
    • 10s of that are timeout-related tests, so...yea.
  • On master, python test.py --no-sftp --no-big-file gets us: Ran 167 tests in 23.485s
    • Or, practically the same runtime as with pytest. So this really does all boil down to the changed stub test crap.

So yea, I'm gonna see about making it so default by-hand tests skip SFTP tests and call it a day. I do not think trying to revert to the global based stuff is worth it (esp since pytest seems to explode on those anyways!) so we'll just have to try rolling forwards (eg in #1101) later instead.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 25, 2017

Decided to do the right thing and use a custom pytest 'slow' marker (as a decorator) to mark the actually slow suites and/or tests. This is both SFTP suites, as a whole, because eh why not; plus anything that runs over 1s normally. Brings inv test down to just about 10-11s.

@bitprophet

This comment has been minimized.

Member

bitprophet commented Oct 25, 2017

OK, this is Done Enough, #1101 will suffice for later. Time to write NEW TESTS.

@bitprophet bitprophet closed this Oct 25, 2017

bitprophet added a commit that referenced this issue Oct 25, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment