dev_appserver occasionally hangs during end-to-end test startup

[derat]

I just saw some failures while running the tests in test/e2e:

2023/01/12 06:59:24 Writing files to /tmp/nup_e2e_test-20230112_065924.1471231028                                                                            
2023/01/12 06:59:31 dev_appserver is listening at http://localhost:35969/                                                                                    
--- FAIL: TestUpdate (10.01s)                                                                                                                                
    tester.go:134: Server timed out (is the app crashing?)                                                                                                   
--- FAIL: TestUserData (10.01s)                                                                                                                              
    tester.go:134: Server timed out (is the app crashing?)                                                                                                   
--- FAIL: TestUpdateUseFilenames (10.01s)                                                                                                                    
    tester.go:134: Server timed out (is the app crashing?)                                                                                                   
--- FAIL: TestUpdateCompare (10.01s)                                                                                                                         
    tester.go:134: Server timed out (is the app crashing?)                                                                                                   
--- FAIL: TestQueries (10.00s)                                                                                                                               
    tester.go:134: Server timed out (is the app crashing?)                                                                                                   
--- FAIL: TestCaching (10.01s)                                                                                                                               
    tester.go:134: Server timed out (is the app crashing?)                                                                                                   
--- FAIL: TestAndroid (10.00s)                                                                                                                               
    tester.go:134: Server timed out (is the app crashing?)                                                                                                   
--- FAIL: TestTags (10.01s)                                                                                                                                  
    tester.go:134: Server timed out (is the app crashing?)                                                                                                   
2023/01/12 07:00:51 Clearing http://localhost:35969/                                                                                                         
2023/01/12 07:00:51 Writing cover and importing songs                                                                                                        
2023/01/12 07:00:51 Writing another cover and updating                                                                                                       
2023/01/12 07:00:52 Writing cover named after recording ID                                                                                                   
2023/01/12 07:00:52 Checking that covers are dumped                                                                                                          
2023/01/12 07:00:52 Clearing http://localhost:35969/                                                                                                         
2023/01/12 07:00:52 Importing songs from JSON                                                                                                                
2023/01/12 07:00:52 Updating song from JSON 
...
2023/01/12 07:00:57 Checking /stats access                                                                                                                   
2023/01/12 07:00:57 Checking that tags are excluded from /tags                                                                                               
2023/01/12 07:00:57 Checking that excluded tags are added to /query                                                                                          
2023/01/12 07:00:57 Checking /song rate-limiting                                                                                                             
FAIL                                                                                                                                                         
FAIL    github.com/derat/nup/test/e2e   96.849s

It looks like the first few tests failed due to the server being unresponsive for 1m30s (a suspiciously round number).

Here's the beginning of the app.log file:

INFO     2023-01-12 10:59:27,404 devappserver2.py:317] Skipping SDK update check.
WARNING  2023-01-12 10:59:28,510 simple_search_stub.py:1196] Could not read search indexes from /tmp/nup_e2e_test-20230112_065924.1471231028/app_storage/search_indexes
INFO     2023-01-12 10:59:28,513 <string>:384] Starting API server at: http://localhost:37245
INFO     2023-01-12 10:59:28,514 instance_factory.py:184] Building with dependencies from go.mod.
INFO     2023-01-12 10:59:28,518 dispatcher.py:280] Starting module "default" running at: http://localhost:35969
INFO     2023-01-12 10:59:28,519 admin_server.py:70] Starting admin server at: http://localhost:46359
INFO     2023-01-12 10:59:32,257 instance.py:294] Instance PID: 19306
2023/01/12 10:59:32 http.ListenAndServe: listen tcp 127.0.0.1:42491: bind: address already in use
INFO     2023-01-12 10:59:33,259 instance.py:294] Instance PID: 19304
INFO     2023-01-12 10:59:33,261 module.py:886] default: "GET // HTTP/1.1" 301 36
INFO     2023-01-12 11:00:51,778 module.py:886] default: "GET // HTTP/1.1" 301 36
INFO     2023-01-12 11:00:51,785 module.py:886] default: "GET / HTTP/1.1" 200 1762
2023/01/12 11:00:51 DEBUG: Clearing all data
INFO     2023-01-12 11:00:51,816 module.py:886] default: "POST /clear HTTP/1.1" 200 2
INFO     2023-01-12 11:00:51,832 module.py:886] default: "POST /flush_cache HTTP/1.1" 200 2
2023/01/12 11:00:51 DEBUG: Inserting song with SHA1 fefac74a1d5928316d7131747107c8a61b71ffe4 and filename "0s.mp3"
2023/01/12 11:00:51 DEBUG: Put song 5629499534213120
...

I guess I saw this in the past, since test/appserver.go already contains this after it's seen that dev_appserver is accepting connections:

    // I was seeing occasional hangs in response to the first request:
    //  ..
    //  INFO     2021-12-06 01:48:34,122 instance.py:294] Instance PID: 18017
    //  INFO     2021-12-06 01:48:34,128 instance.py:294] Instance PID: 18024
    //  2021/12/06 01:48:34 http.ListenAndServe: listen tcp 127.0.0.1:20020: bind: address already in use
    //  INFO     2021-12-06 01:48:34,143 module.py:883] default: "POST /config HTTP/1.1" 200 2
    //
    // I think the http.ListenAndServer call comes from the appengine.Main call in the app's main
    // function. Oddly, the port is always already bound by the app itself. My best guess is that
    // there's a race in dev_appserver.py that can be triggered when a request comes in soon after
    // it starts handling requests. It happens infrequently, and I've still seen the error at least
    // once with a 1-second delay. It didn't happen across dozens of runs with a 3-second delay,
    // though.
    time.Sleep(3 * time.Second)

    return &srv, nil

Maybe I need to increase the delay even more? dev_appserver is buggy, but I don't think there's any other way to emulate all of the App Engine features that I'm using.