pushup: The tests don't pass on main on macOS

I started to look into it, but the TestPushup function is pretty hard to understand

$ go test ./...
--- FAIL: TestPushup (8.10s)
    --- FAIL: TestPushup/$name.pushup (1.19s)
        --- FAIL: TestPushup/$name.pushup/0.conf (0.65s)
            main_test.go:256: stderr:
                [PUSHUP] GET /testdata/Pushup 200 24.75µs
                2022/08/31 08:24:16 SIGNAL TRAPPED
                [PUSHUP] shutting down gracefully, press Ctrl+C to force immediate
                [PUSHUP] shutdown complete

            main_test.go:257: error: *os.SyscallError wait: no child processes
        --- FAIL: TestPushup/$name.pushup/#00 (0.54s)
            main_test.go:256: stderr:
                [PUSHUP] GET /testdata/world 200 13.875µs
                2022/08/31 08:24:16 SIGNAL TRAPPED
                [PUSHUP] shutting down gracefully, press Ctrl+C to force immediate
                [PUSHUP] shutdown complete

            main_test.go:257: error: *os.SyscallError wait: no child processes
    --- FAIL: TestPushup/attributes.pushup (0.57s)
        --- FAIL: TestPushup/attributes.pushup/#00 (0.57s)
            main_test.go:256: stderr:
                [PUSHUP] GET /testdata/attributes 200 13.792µs
                2022/08/31 08:24:17 SIGNAL TRAPPED
                [PUSHUP] shutting down gracefully, press Ctrl+C to force immediate
                [PUSHUP] shutdown complete

            main_test.go:257: error: *os.SyscallError wait: no child processes
    --- FAIL: TestPushup/handler.pushup (0.54s)
        --- FAIL: TestPushup/handler.pushup/#00 (0.54s)
            main_test.go:256: stderr:
                [PUSHUP] GET /testdata/handler 418 5.833µs
                2022/08/31 08:24:18 SIGNAL TRAPPED
                [PUSHUP] shutting down gracefully, press Ctrl+C to force immediate
                [PUSHUP] shutdown complete

            main_test.go:257: error: *os.SyscallError wait: no child processes
    --- FAIL: TestPushup/if.pushup (0.55s)
        --- FAIL: TestPushup/if.pushup/#00 (0.55s)
            main_test.go:256: stderr:
                [PUSHUP] GET /testdata/if 200 30.334µs
                2022/08/31 08:24:19 SIGNAL TRAPPED
                [PUSHUP] shutting down gracefully, press Ctrl+C to force immediate
                [PUSHUP] shutdown complete

            main_test.go:257: error: *os.SyscallError wait: no child processes
    --- FAIL: TestPushup/index.pushup (0.54s)
        --- FAIL: TestPushup/index.pushup/#00 (0.54s)
            main_test.go:256: stderr:
                [PUSHUP] GET /testdata/ 200 18.875µs
                2022/08/31 08:24:19 SIGNAL TRAPPED
                [PUSHUP] shutting down gracefully, press Ctrl+C to force immediate
                [PUSHUP] shutdown complete

            main_test.go:257: error: *os.SyscallError wait: no child processes
    --- FAIL: TestPushup/panicking.pushup (0.54s)
        --- FAIL: TestPushup/panicking.pushup/#00 (0.54s)
            main_test.go:256: stderr:
                2022/08/31 08:24:20 recovered from panic in an HTTP hander:
                goroutine 34 [running]:
                runtime/debug.Stack()
                	/opt/homebrew/Cellar/go/1.19/libexec/src/runtime/debug/stack.go:24 +0x64
                runtime/debug.PrintStack()
                	/opt/homebrew/Cellar/go/1.19/libexec/src/runtime/debug/stack.go:16 +0x1c
                main.panicRecoveryMiddleware.func1.1()
                	/Users/llimllib/adhoc/innovation/pushup/main/build/cmd/myproject/main.go:126 +0x64
                panic({0x1008d0020, 0x1008ab3c0})
                	/opt/homebrew/Cellar/go/1.19/libexec/src/runtime/panic.go:884 +0x204
                github.com/AdHocRandD/pushup/build.(*TestdataPanickingPage).Respond(0x10092b7d8?, {0x1400020c140?, 0x1008e0d20?}, 0x100b08c50?)
                	panicking.pushup:2 +0x48
                github.com/AdHocRandD/pushup/build.Respond({0x10092b160, 0x140002120a0}, 0x14000226000)
                	/Users/llimllib/adhoc/innovation/pushup/main/build/pushup_support.go:110 +0x27c
                main.pushupHandler({0x10092b160, 0x140002120a0}, 0x14000226000)
                	/Users/llimllib/adhoc/innovation/pushup/main/build/cmd/myproject/main.go:111 +0x1a8
                net/http.HandlerFunc.ServeHTTP(0x1?, {0x10092b160?, 0x140002120a0?}, 0x1007bf450?)
                	/opt/homebrew/Cellar/go/1.19/libexec/src/net/http/server.go:2109 +0x38
                main.requestLogMiddleware.func1({0x10092b340?, 0x1400023e000}, 0x14000226000)
                	/Users/llimllib/adhoc/innovation/pushup/main/build/cmd/myproject/main.go:167 +0xbc
                net/http.HandlerFunc.ServeHTTP(0x0?, {0x10092b340?, 0x1400023e000?}, 0x100d6e128?)
                	/opt/homebrew/Cellar/go/1.19/libexec/src/net/http/server.go:2109 +0x38
                main.panicRecoveryMiddleware.func1({0x10092b340?, 0x1400023e000?}, 0x100d6e03b?)
                	/Users/llimllib/adhoc/innovation/pushup/main/build/cmd/myproject/main.go:130 +0x74
                net/http.HandlerFunc.ServeHTTP(0x14000117ad8?, {0x10092b340?, 0x1400023e000?}, 0x0?)
                	/opt/homebrew/Cellar/go/1.19/libexec/src/net/http/server.go:2109 +0x38
                net/http.(*ServeMux).ServeHTTP(0x0?, {0x10092b340, 0x1400023e000}, 0x14000226000)
                	/opt/homebrew/Cellar/go/1.19/libexec/src/net/http/server.go:2487 +0x140
                net/http.serverHandler.ServeHTTP({0x1400020a150?}, {0x10092b340, 0x1400023e000}, 0x14000226000)
                	/opt/homebrew/Cellar/go/1.19/libexec/src/net/http/server.go:2947 +0x2c4
                net/http.(*conn).serve(0x1400021c000, {0x10092b880, 0x1400020a0c0})
                	/opt/homebrew/Cellar/go/1.19/libexec/src/net/http/server.go:1991 +0x560
                created by net/http.(*Server).Serve
                	/opt/homebrew/Cellar/go/1.19/libexec/src/net/http/server.go:3102 +0x444
                2022/08/31 08:24:20 SIGNAL TRAPPED
                [PUSHUP] shutting down gracefully, press Ctrl+C to force immediate
                [PUSHUP] shutdown complete

            main_test.go:257: error: *os.SyscallError wait: no child processes
    --- FAIL: TestPushup/request_basic.pushup (0.55s)
        --- FAIL: TestPushup/request_basic.pushup/#00 (0.54s)
            main_test.go:256: stderr:
                [PUSHUP] GET /testdata/request_basic 200 18.5µs
                2022/08/31 08:24:22 SIGNAL TRAPPED
                [PUSHUP] shutting down gracefully, press Ctrl+C to force immediate
                [PUSHUP] shutdown complete

            main_test.go:257: error: *os.SyscallError wait: no child processes
    --- FAIL: TestPushup/textelement.pushup (0.56s)
        --- FAIL: TestPushup/textelement.pushup/#00 (0.56s)
            main_test.go:256: stderr:
                [PUSHUP] GET /testdata/textelement 200 15.083µs
                2022/08/31 08:24:23 SIGNAL TRAPPED
                [PUSHUP] shutting down gracefully, press Ctrl+C to force immediate
                [PUSHUP] shutdown complete

            main_test.go:257: error: *os.SyscallError wait: no child processes
FAIL
FAIL	github.com/AdHocRandD/pushup	8.422s
?   	github.com/AdHocRandD/pushup/build	[no test files]
?   	github.com/AdHocRandD/pushup/build/cmd/myproject	[no test files]
?   	github.com/AdHocRandD/pushup/scaffold/pkg	[no test files]
FAIL

About this issue

Original URL
State: closed
Created 2 years ago
Comments: 22 (22 by maintainers)

Commits related to this issue

remove cmd.Wait in test process killing goroutine See https://github.com/adhocteam/pushup/issues/38 for evidence that it's causing #38. I can't say that I have a good theory for _why_, but empiricall... — committed to adhocteam/pushup by llimllib a year ago

Most upvoted comments

I pushed my instrumentation code to the instrument-test-failure branch. When a test succeeds, you’ll see something like:

    main_test.go:166: /var/folders/cj/3fpctnd52vv37y9gpdgg7c200000gn/T/TestPushup3617381832/001/pushup.exe run -build-pkg github.com/adhocteam/pushup/build -page testdata/attributes.up -unix-socket /var/folders/cj/3fpctnd52vv37y9gpdgg7c200000gn/T/pushup282877214/sock
    main_test.go:195: launching read output
    main_test.go:229: waiting to kill
    main_test.go:247: making request
    main_test.go:288: waiting
    main_test.go:297: checking error
    main_test.go:185: waiting for build process to finish, 60590
    main_test.go:213: read output, needle found
    main_test.go:284: request completed
    main_test.go:233: done, killing -60590
    main_test.go:238: killed
    main_test.go:191: pushup process done
    main_test.go:291: wait completed
    main_test.go:294: closes completed

When it fails, you get something like:

=== RUN   TestPushup/empty.up/#00
    main_test.go:166: /var/folders/cj/3fpctnd52vv37y9gpdgg7c200000gn/T/TestPushup3617381832/001/pushup.exe run -build-pkg github.com/adhocteam/pushup/build -page testdata/empty.up -unix-socket /var/folders/cj/3fpctnd52vv37y9gpdgg7c200000gn/T/pushup4194445339/sock
    main_test.go:195: launching read output
    main_test.go:229: waiting to kill
    main_test.go:247: making request
    main_test.go:288: waiting
    main_test.go:297: checking error
    main_test.go:185: waiting for build process to finish, 60614
    main_test.go:213: read output, needle found
    main_test.go:284: request completed
    main_test.go:233: done, killing -60614
    main_test.go:238: killed

You can see that the pushup process done log - which fires right after the cmd.Wait for the pushup run process - never happen.

So it seems like Wait isn’t returning, despite the fact that process 60614 is dead, and the process just sits there for 10 minutes until the timeout finally throws.

$ ps aux | grep 6061
llimllib         63105   0.0  0.0 408626880   1312 s009  S+    3:11PM   0:00.00 grep 6061

llimllib on Jan 5, 2023