"Filter Not Found" random exception with Geth and Web3J

[kunalbarchha]

Web3J version - 5.0.0 Geth version - 1.9.14 -Stable Ubuntu 18.04 - 64-bit 32GB RAM 1.9 TB HDD Geth fully synced and running JDK - 1.8 Spring - 1.5

I have two subscription method defined as @PostConstruct : TransactionFlowable and BlockFlowable.

The problem is that the transactionFlowable subscription randomly throws "Filter Not Found" exception. It runs for few minutes to few hours. When I check Geth, it is running perfectly fine and syncing new incoming blocks.

I have checked Web3J issues, StackOverflow, and what not. Somehow there are many people facing this issue, but there is no working solution posted. Some solutions are dated back to 2018, which are not relevant with latest version.

If someone can help out on the issue, that will be really nice. Need to run both the subscription reliably for production, 24x7.

Below is the code Snippet:

@PostConstruct
public void start() throws OnErrorNotImplementedException, ConnectException {

WebSocketService socketService = new WebSocketService(config.getMainNetSocket(), true);        web3J();
log.info("Started >>>>>>> ");

Web3j web3jSocket = Web3j.build(socketService);
socketService.connect();

synchronized (this) {
    Disposable subscription = web3jSocket.transactionFlowable().subscribe(
            tx ->
            {
                log.info("Tx Hash > " + tx.getHash());
                getTransactionByHash(tx.getHash());

            }, throwable -> {
                log.info("Message >>>> " + throwable.getMessage());
                throwable.printStackTrace();
            });
}

Exception Log:

2020-06-10 11:27:25.284  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Tx Hash > 0x3ee4adbe9789189662cdc3d61655a4b68845c791f01c37db83c7e53ba8fa0a4c
2020-06-10 11:27:26.758  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Got To Address >>>> 0x72ebd62060f78d91dc4bc33e8d88f39307365f87
2020-06-10 11:27:26.760  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Tx Hash > 0x3d50ebcdb3fa95e81d9ef8f4ee978a80d3aa5a43b8d274d9f4860ee440d36e27
2020-06-10 11:27:28.187  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Got To Address >>>> 0xdac17f958d2ee523a2206206994597c13d831ec7
2020-06-10 11:27:28.189  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Tx Hash > 0xde55b36788acdfcf75fe080f1ca808a24e1e8e70bb266e0c6ce875892959d5d5
2020-06-10 11:27:29.602  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Got To Address >>>> 0x47dcfcaf9aca005cbe955fbaff11165e70d28bca
2020-06-10 11:27:29.603  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Tx Hash > 0x7592438f0a11f6cdcfb2f8374f8ffb5a2e7f6d0b1605b57676bfd0e26f9de2ff
2020-06-10 11:27:31.020  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Got To Address >>>> 0xca9ca2dabf9024e7588ab10c8c2116f5809fa561
2020-06-10 11:27:31.023  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Tx Hash > 0x3f36cd6caaa8b3d158bb3b6535cbe7502925a85ac44c405857473cec9aa8ee9f
2020-06-10 11:27:32.439  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Got To Address >>>> 0xdac17f958d2ee523a2206206994597c13d831ec7
2020-06-10 11:27:32.441  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Tx Hash > 0xd42751dded2588e9152bf3d81b3f84b729ee3aa17e6b46ebc8cbf09ee14e35bd
2020-06-10 11:27:34.639  INFO 20268 --- [pool-9-thread-1] c.c.e.c.e.services.SubscriptionService   : Got To Address >>>> 0x98ad263a95f1ab1abff41f4d44b07c3240251a0a
2020-06-10 11:27:34.643  WARN 20268 --- [pool-9-thread-2] org.web3j.protocol.core.filters.Filter   : The filter has not been found. Filter id: 66674882484826508490032443079398703497
2020-06-10 11:27:34.654 ERROR 20268 --- [pool-9-thread-2] org.web3j.protocol.core.filters.Filter   : Error sending request

org.web3j.protocol.core.filters.FilterException: Error sending request
at org.web3j.protocol.core.filters.Filter.throwException(Filter.java:194) ~[core-5.0.0.jar:na]
at org.web3j.protocol.core.filters.Filter.run(Filter.java:104) ~[core-5.0.0.jar:na]
at org.web3j.protocol.core.filters.Filter.reinstallFilter(Filter.java:155) ~[core-5.0.0.jar:na]
at org.web3j.protocol.core.filters.Filter.pollFilter(Filter.java:137) ~[core-5.0.0.jar:na]
at org.web3j.protocol.core.filters.Filter.lambda$run$0(Filter.java:92) ~[core-5.0.0.jar:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_241]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[na:1.8.0_241]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_241]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[na:1.8.0_241]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_241]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_241]
at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_241]
Caused by: java.io.IOException: Interrupted WebSocket request
at org.web3j.protocol.websocket.WebSocketService.send(WebSocketService.java:168) ~[core-5.0.0.jar:na]
at org.web3j.protocol.core.Request.send(Request.java:87) ~[core-5.0.0.jar:na]
at org.web3j.protocol.core.filters.BlockFilter.sendRequest(BlockFil

ter.java:34) ~[core-5.0.0.jar:na]
at org.web3j.protocol.core.filters.Filter.run(Filter.java:59) ~[core-5.0.0.jar:na]
... 10 common frames omitted
Caused by: java.lang.InterruptedException: null
at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:347) ~[na:1.8.0_241]
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1908) ~[na:1.8.0_241]
at org.web3j.protocol.websocket.WebSocketService.send(WebSocketService.java:165) ~[core-5.0.0.jar:na]
... 13 common frames omitted

[i-norden]

This looks like a likely culprit. If a filter goes stale and is removed then that error could be thrown here or here.

[holiman]

This looks like a likely culprit. If a filter goes stale and is removed then that error could be thrown here or here.

Well, the linked places does throw fmt.Errorf("filter not found"), but that exact sentence is not present in the logs. What we do see, however, is

Caused by: java.io.IOException: Interrupted WebSocket request
at org.web3j.protocol.websocket.WebSocketService.send(WebSocketService.java:168) ~[core-5.0.0.jar:na]
at org.web3j.protocol.core.Request.send(Request.java:87) ~[core-5.0.0.jar:na]
at org.web3j.protocol.core.filters.BlockFilter.sendRequest(BlockFil

So the cause might just as well be some websocket error. If geth returned an actual error to a json-rpc request, I would assume that the error message would be surfaced and included in the java log...?

[ligi]

@i-norden it would be really helpful if you could provide us with the code to reproduce the issue - ideally reduced to the minimum that triggers the problem.

[i-norden]

@ligi sorry for the confusion, it's not my error/issue. I was just throwing a potential lead out there.

[kunalbarchha]

@ligi That's my error.

"2020-06-10 11:27:34.643 WARN 20268 --- [pool-9-thread-2] org.web3j.protocol.core.filters.Filter : The filter has not been found. Filter id: 66674882484826508490032443079398703497"

I am subscribing to pending transaction, it works perfectly fine for few minutes, but after that it throws above mentioned error. The same happens with block subscription. In short, Geth removes the filter after sometime and that causes this error.

Google " Random Filter not found web3j" the issue is dated back to 2017 and I wonder why no one has yet posted it here.

P.S : I tried running the local instance of GETH after full sync and also on Infura. The problem is same. I also talked with Infura support and they said it is a general issue most are facing. However, no one gave me a production-ready solution to this problem.
Below is the minimum code to reproduce the error:

WebSocketService socketService = new WebSocketService("wss://mainnet.infura.io/ws/v3/<infura token>", true);
    Web3j web3j = Web3j.build(new HttpService("https://rinkeby.infura.io/v3/<infura token>"));

    @PostConstruct
    public void start() throws OnErrorNotImplementedException, ConnectException {

        log.info("Started >>>>>>> ");

        Web3j web3jSocket = Web3j.build(socketService);
        socketService.connect();

        web3jSocket.transactionFlowable().subscribe(tx ->
                {
                    log.info("Tx Hash > " +tx.getHash());
//                    saveTxHash(tx.getHash());

//                }, throwable -> {
//                    log.info("Message >>>> "+throwable.getMessage());
//                        throwable.printStackTrace();
                        }); 

[kunalbarchha]

I think @i-norden 's comment makes sense : https://github.com/ethereum/go-ethereum/blob/master/eth/filters/api.go#L77

I have tried tracking the time it takes to throw that exception, and it is usually in multiple of 5.

[ligi]

hm - I can't seem to repro it with the code you gave - running over 5min now - output here: https://gist.github.com/ligi/d7f8b0aeb19bbc81bf946249c3c553a2
code here: https://github.com/ligi/GethIssue21386

[ligi]

dam - directly after sending this issue I got that error:

io.reactivex.exceptions.OnErrorNotImplementedException: The exception was not handled due to missing onError handler in the subscribe() method call. Further reading: https://github.com/ReactiveX/RxJava/wiki/Error-Handling | null
	at io.reactivex.internal.functions.Functions$OnErrorMissingConsumer.accept(Functions.java:704)
	at io.reactivex.internal.functions.Functions$OnErrorMissingConsumer.accept(Functions.java:701)
	at io.reactivex.internal.subscribers.LambdaSubscriber.onError(LambdaSubscriber.java:79)
	at io.reactivex.internal.operators.flowable.FlowableFlattenIterable$FlattenIterableSubscriber.drain(FlowableFlattenIterable.java:275)
	at io.reactivex.internal.operators.flowable.FlowableFlattenIterable$FlattenIterableSubscriber.onNext(FlowableFlattenIterable.java:174)
	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.tryEmitScalar(FlowableFlatMap.java:234)
	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:152)
	at io.reactivex.internal.operators.flowable.FlowableCreate$BufferAsyncEmitter.drain(FlowableCreate.java:547)
	at io.reactivex.internal.operators.flowable.FlowableCreate$BufferAsyncEmitter.onNext(FlowableCreate.java:471)
	at org.web3j.protocol.core.filters.BlockFilter.process(BlockFilter.java:42)
	at org.web3j.protocol.core.filters.Filter.pollFilter(Filter.java:144)
	at org.web3j.protocol.core.filters.Filter.lambda$run$0(Filter.java:92)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.NullPointerException
	at org.web3j.protocol.rx.JsonRpc2_0Rx.toTransactions(JsonRpc2_0Rx.java:252)
	at io.reactivex.internal.operators.flowable.FlowableFlattenIterable$FlattenIterableSubscriber.drain(FlowableFlattenIterable.java:265)
	... 15 more
Exception in thread "pool-3-thread-2" io.reactivex.exceptions.OnErrorNotImplementedException: The exception was not handled due to missing onError handler in the subscribe() method call. Further reading: https://github.com/ReactiveX/RxJava/wiki/Error-Handling | null
	at io.reactivex.internal.functions.Functions$OnErrorMissingConsumer.accept(Functions.java:704)
	at io.reactivex.internal.functions.Functions$OnErrorMissingConsumer.accept(Functions.java:701)
	at io.reactivex.internal.subscribers.LambdaSubscriber.onError(LambdaSubscriber.java:79)
	at io.reactivex.internal.operators.flowable.FlowableFlattenIterable$FlattenIterableSubscriber.drain(FlowableFlattenIterable.java:275)
	at io.reactivex.internal.operators.flowable.FlowableFlattenIterable$FlattenIterableSubscriber.onNext(FlowableFlattenIterable.java:174)
	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.tryEmitScalar(FlowableFlatMap.java:234)
	at io.reactivex.internal.operators.flowable.FlowableFlatMap$MergeSubscriber.onNext(FlowableFlatMap.java:152)
	at io.reactivex.internal.operators.flowable.FlowableCreate$BufferAsyncEmitter.drain(FlowableCreate.java:547)
	at io.reactivex.internal.operators.flowable.FlowableCreate$BufferAsyncEmitter.onNext(FlowableCreate.java:471)
	at org.web3j.protocol.core.filters.BlockFilter.process(BlockFilter.java:42)
	at org.web3j.protocol.core.filters.Filter.pollFilter(Filter.java:144)
	at org.web3j.protocol.core.filters.Filter.lambda$run$0(Filter.java:92)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.NullPointerException
	at org.web3j.protocol.rx.JsonRpc2_0Rx.toTransactions(JsonRpc2_0Rx.java:252)
	at io.reactivex.internal.operators.flowable.FlowableFlattenIterable$FlattenIterableSubscriber.drain(FlowableFlattenIterable.java:265)
	... 15 more

[kunalbarchha]

@ligi You are getting different exception because you have not implemented OnErrorNotImplemented exception. if you surround it in try and catch, then print the exception message that you receive from Geth, it will likely be "Filter Not Found".

[ligi]

Yea - just wrapped your code with a gradle script so the one that wants to look at it from the go side does not need to deal with java tooling ..

[kunalbarchha]

Noted. I talked with Nethereum dev on Gitter and also with Web3J guy on Gitter, it has something to do with Filter being deleted by Geth. That was the same reply I got from Infura support.