HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded test failure

[bryce-anderson]

https://github.com/apple/servicetalk/actions/runs/6848710363/job/18619420912#step:7:1529

HttpMessageDiscardWatchdogServiceFilterTest > warnsIfDiscarded(ResponseTransformer) > warnsIfDiscarded(ResponseTransformer) [3] transformer=Drops message body while transforming FAILED
    org.opentest4j.AssertionFailedError: expected: <true> but was: <false>
        at org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
        at org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
        at org.junit.jupiter.api.AssertTrue.failNotTrue(AssertTrue.java:63)
        at org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:36)
        at org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:31)
        at org.junit.jupiter.api.Assertions.assertTrue(Assertions.java:180)
        at io.servicetalk.http.netty.HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(HttpMessageDiscardWatchdogServiceFilterTest.java:95)

HttpMessageDiscardWatchdogServiceFilterTest > warnsIfDiscarded(ResponseTransformer) > warnsIfDiscarded(ResponseTransformer) [4] transformer=Drops response and creates new one FAILED
    org.opentest4j.AssertionFailedError: expected: <true> but was: <false>
        at org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
        at org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
        at org.junit.jupiter.api.AssertTrue.failNotTrue(AssertTrue.java:63)
        at org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:36)
        at org.junit.jupiter.api.AssertTrue.assertTrue(AssertTrue.java:31)
        at org.junit.jupiter.api.Assertions.assertTrue(Assertions.java:180)
        at io.servicetalk.http.netty.HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(HttpMessageDiscardWatchdogServiceFilterTest.java:95)

[bryce-anderson]

Here is the failed assertion: https://github.com/apple/servicetalk/blob/main/servicetalk-http-netty/src/test/java/io/servicetalk/http/netty/HttpMessageDiscardWatchdogServiceFilterTest.java#L95

It looks like we give the test 1 second to accumulate logs.
@daschl, do you think this test just needs a bit more time to get the log entry?

[bryce-anderson]

Closed via #2757.

[bryce-anderson]

Still broken: https://github.com/apple/servicetalk/actions/runs/6897145342/job/18764729861#step:7:1614

[bryce-anderson]

Adding the entire log output so we can more easily debug when it fails again: #2762

[bryce-anderson]

A hit on the test again which spilled the logs:

java.lang.AssertionError: Logs didn't contain the expected output:
2023-12-04 09:55:07,118        ForkJoinPool-1-worker-1 [ERROR] LoggerStringWriter             - forced log entry to help for flush on current thread 6847363805439087069

	at io.servicetalk.http.netty.HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(HttpMessageDiscardWatchdogServiceFilterTest.java:97)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

If I had to bet on it, the tests may be running concurrently with other tests that use the same tooling.

[bryce-anderson]

There are probably a few ways we can adjust the LoggerStringWriter to make it more thread-safe. We could do the simple thing and make it something you need to instantiate as part of your tests in which case it can have test-local state. The downside is that breaks the API and since it's published it's possible it's used in places outside our control.

If we want to preserve the API we can also try to make the state thread-local. It seems the key is registration and deregistration of a logger. We can probably give it name based on the local environment without changing the API.

[bryce-anderson]

We don't know for sure that the changes in #2771 fixed this so it wouldn't be a huge surprise if this pops again.

[bryce-anderson]

Popped again: https://github.com/apple/servicetalk/actions/runs/7451782820/job/20273613156#step:7:1898
Relavent output:

HttpMessageDiscardWatchdogServiceFilterTest > warnsIfDiscarded(ResponseTransformer) > warnsIfDiscarded(ResponseTransformer) [3] transformer=Drops message body while transforming FAILED
    java.lang.AssertionError: Logs didn't contain the expected output:
Error: 4-01-08 18:57:05,142        ForkJoinPool-1-worker-1 [ERROR] LoggerStringWriter             - forced log entry to help for flush on current thread -8531150189973640691
        at io.servicetalk.http.netty.HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(HttpMessageDiscardWatchdogServiceFilterTest.java:99)

From the test it looks like the only log message is the flush entry.

[daschl]

@bryce-anderson hm, so it looks like the LoggerStringWriter was not the issue here... 🤔

[idelpivnitskiy]

A few more cases with enhanced logging:

https://github.com/apple/servicetalk/runs/21828666352

HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(ResponseTransformer) [3] transformer=Drops message body while transforming
java.lang.AssertionError: Logs didn't contain the expected output:
-- START OUTPUT--
2024-02-21 17:40:17,847        ForkJoinPool-1-worker-1 [INFO ] HttpMessageDiscardWatchdogServiceFilterTest - Logger initialized
2024-02-21 17:40:17,888        ForkJoinPool-1-worker-1 [ERROR] LoggerStringWriter             - forced log entry to help for flush on current thread -5498676091586310967

-- END OUTPUT --
	at io.servicetalk.http.netty.HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(HttpMessageDiscardWatchdogServiceFilterTest.java:109)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)

https://github.com/apple/servicetalk/runs/21835835925

HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(ResponseTransformer) [3] transformer=Drops message body while transforming
java.lang.AssertionError: Logs didn't contain the expected output:
-- START OUTPUT--
2024-02-21 20:54:46,481        ForkJoinPool-1-worker-1 [INFO ] HttpMessageDiscardWatchdogServiceFilterTest - Logger initialized
2024-02-21 20:54:46,514        ForkJoinPool-1-worker-1 [ERROR] LoggerStringWriter             - forced log entry to help for flush on current thread 1637164911302841071

-- END OUTPUT --
	at io.servicetalk.http.netty.HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(HttpMessageDiscardWatchdogServiceFilterTest.java:109)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)

HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(ResponseTransformer) [4] transformer=Drops response and creates new one
java.lang.AssertionError: Logs didn't contain the expected output:
-- START OUTPUT--
2024-02-21 20:54:46,550        ForkJoinPool-1-worker-1 [INFO ] HttpMessageDiscardWatchdogServiceFilterTest - Logger initialized
2024-02-21 20:54:46,575        ForkJoinPool-1-worker-1 [ERROR] LoggerStringWriter             - forced log entry to help for flush on current thread -5014449611528047618

-- END OUTPUT --
	at io.servicetalk.http.netty.HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(HttpMessageDiscardWatchdogServiceFilterTest.java:109)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)

[idelpivnitskiy]

https://github.com/apple/servicetalk/runs/21838036035

HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(ResponseTransformer) [2] transformer=Drops payload body while transforming
java.lang.AssertionError: Logs didn't contain the expected output:
-- START OUTPUT--
2024-02-21 21:59:49,997        ForkJoinPool-1-worker-1 [INFO ] HttpMessageDiscardWatchdogServiceFilterTest - Logger initialized
2024-02-21 21:59:50,038        ForkJoinPool-1-worker-1 [ERROR] LoggerStringWriter             - forced log entry to help for flush on current thread -195339993080982798

-- END OUTPUT --
	at io.servicetalk.http.netty.HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded(HttpMessageDiscardWatchdogServiceFilterTest.java:109)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)