search

apple / servicetalk

A networking framework that evolves with your application
https://docs.servicetalk.io
Apache License 2.0
927 stars 181 forks source link

HttpMessageDiscardWatchdogServiceFilterTest.warnsIfDiscarded test failure #2756

Open bryce-anderson opened 1 year ago

bryce-anderson commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

Closed via https://github.com/apple/servicetalk/pull/2757.

bryce-anderson commented 1 year ago

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

bryce-anderson commented 1 year ago

Adding the entire log output so we can more easily debug when it fails again: https://github.com/apple/servicetalk/pull/2762

bryce-anderson commented 11 months ago

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 commented 11 months ago

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 commented 11 months ago

We don't know for sure that the changes in https://github.com/apple/servicetalk/pull/2771 fixed this so it wouldn't be a huge surprise if this pops again.

bryce-anderson commented 10 months ago

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 commented 10 months ago

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

idelpivnitskiy commented 9 months ago

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 commented 9 months ago

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)