ServiceLoader is not instantiating the command handler classes about nostr-java

[tcheeric]

I have finally found the issue with the ServiceLoader!

[tcheeric]

NOW, the Problem I am facing, is that the ServiceLoader is not instantiating the handler classes (See here).

About this problem, I observed that you instanced the listener in ConnectionImpl as an OpenListener, but how the WebSocket will know when call TextListener, CloseListener or whatever? It's not clear for me. I did a test and got success just changing OpenListener to TextListener.

Log:

abr. 21, 2024 12:14:32 PM jdk.internal.net.http.HttpClientImpl$SelectorManager run
FINE: [HttpClient-1-SelectorManager] [15s 778ms] HttpClientImpl(1) Next deadline is 3000
abr. 21, 2024 12:14:34 PM nostr.connection.impl.WebsocketClientListeners$TextListener handleReceivedText
INFO: Received message ["OK","6d83330b8d77b5868589f247015f658da1a95eed93f5d817b486cc9ee07cfa22",true,""] from Relay(uri=nostr.mom)
abr. 21, 2024 12:14:34 PM nostr.connection.impl.WebsocketClientListeners$TextListener handleReceivedText
INFO: Creating the command context with message OkMessage(eventId=6d83330b8d77b5868589f247015f658da1a95eed93f5d817b486cc9ee07cfa22, flag=true, message=)
abr. 21, 2024 12:14:34 PM jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask processText
FINE: [HttpClient-1-Worker-0] [18s 383ms] [WebSocket] exit onText 2 returned java.util.concurrent.CompletableFuture@279f774e[Completed exceptionally: java.util.concurrent.CompletionException: java.lang.NullPointerException: Cannot invoke "nostr.context.impl.DefaultRequestContext.getPrivateKey()" because "this.context" is null]
abr. 21, 2024 12:14:34 PM jdk.internal.net.http.websocket.WebSocketImpl tryChangeState
FINE: [HttpClient-1-Worker-0] [18s 383ms] [WebSocket] change state from TEXT to IDLE true
abr. 21, 2024 12:14:34 PM jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask run
FINE: [HttpClient-1-Worker-0] [18s 383ms] [WebSocket] receive state: IDLE
abr. 21, 2024 12:14:34 PM jdk.internal.net.http.websocket.WebSocketImpl tryChangeState
FINE: [HttpClient-1-Worker-0] [18s 383ms] [WebSocket] change state from IDLE to WAITING true
abr. 21, 2024 12:14:34 PM jdk.internal.net.http.websocket.TransportImpl request

I have found a solution. Look at how I now use the CompositeListener class to pass all listeners.
Also, in the ConnectionImpl, I was throwing an exception in the connect when the connection was failing. This is what, I believe, was causing all subsequent connection attempts to fail. I have now removed the throwing of the RuntimeException and I am logging an exception instead. This seems to work. (See here)

A COUPLE OF THINGS that I forgot to mention:

1. You have surely seen that I am not using the jetty library any more to handle ws connections
2. Also, please always add the URI scheme of the relay in the properties file, e.g. ws://localhost:3333 (instead of just localhost:3333) - Although I think probing for https and http is necessary, I don't think it should be handled here, but at client level instead. I want to move away from it, also to make things less complex and more intuitive.

NOW, with these issues solved, my original problem should become apparent: the ServiceLoader still does not instantiate the command handlers (ok, eose, auth etc.)

[guilhermegps]

Ok, I will take a look and answer you soon.

[guilhermegps]

I'd like to simulate your problem here. How can I do this?

What is the test that you are trying?

What is the branch that I need to look? 0.6-SNAPSHOT ?

About your points:

1. Nice, good change. This is a really problem that we have.

2. Agree

3. I'd like to say that we need to have caution with the module changes, because this kind of change could broke application that is using an oldest version and decide to upgrade for this new version. Said it, I need to agree that modules more intuitive are better.

[tcheeric]

Branch is 0.6-SNAPSHOT

When you receive a message from a relay (ok, eose, notice etc) we use the service locator to instantiate the corresponding command handler class (default or custom) and run its handle method. This doesn't work, the service locator doesn't find the handler classes. This is what I'm struggling with at the moment. It seems so obvious but I can't find where the problem is.

Agree re. caution with module changes but I saw these modifications as necessary. For clients, this would hopefully not be too much to change, just a bit of refactoring, changing their custom handlers, and create separate classes for each instead.

Thanks.

[guilhermegps]

@tcheeric

I found a problem with this change, the example of "filters" broke, it's not necessary to sign a request for search events, they are public.

[guilhermegps]

Well, I'm getting a problem when try to connect with relays. When happened any problem during the connection with relay, I get an error here and all connections with all relays stop and no event is sent.

abr. 20, 2024 11:03:41 AM jdk.internal.net.http.HttpClientImpl$SelectorManager run
FINE: [HttpClient-1-SelectorManager] [96ms] HttpClientImpl(1) Next deadline is 3000
abr. 20, 2024 11:03:41 AM nostr.examples.NostrApiExamples lambda$0
SEVERE: java.util.concurrent.ExecutionException: java.lang.RuntimeException: Failed to connect to Relay(uri=nostr.zebedee.cloud)
java.lang.RuntimeException: java.util.concurrent.ExecutionException: java.lang.RuntimeException: Failed to connect to Relay(uri=nostr.zebedee.cloud)
	at nostr.util/nostr.util.thread.ThreadUtil.run(ThreadUtil.java:51)
	at nostr.client/nostr.client.Client.connect(Client.java:52)
	at nostr.api/nostr.api.Nostr.send(Nostr.java:145)
	at nostr.api/nostr.api.Nostr.send(Nostr.java:113)
	at nostr.api/nostr.api.EventNostr.send(EventNostr.java:46)
	at nostr.examples/nostr.examples.NostrApiExamples.sendTextNoteEvent(NostrApiExamples.java:196)
	at nostr.examples/nostr.examples.NostrApiExamples.lambda$0(NostrApiExamples.java:99)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:577)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1589)
Caused by: java.util.concurrent.ExecutionException: java.lang.RuntimeException: Failed to connect to Relay(uri=nostr.zebedee.cloud)
	at java.base/java.util.concurrent.FutureTask.report(FutureTask.java:122)
	at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:205)
	at nostr.util/nostr.util.thread.ThreadUtil.run(ThreadUtil.java:48)
	... 11 more
Caused by: java.lang.RuntimeException: Failed to connect to Relay(uri=nostr.zebedee.cloud)
	at nostr.connection/nostr.connection.impl.ConnectionImpl.connect(ConnectionImpl.java:60)
	at java.base/java.lang.Iterable.forEach(Iterable.java:75)
	at nostr.connection/nostr.connection.impl.ConnectionPool.connect(ConnectionPool.java:40)
	at nostr.client/nostr.client.Client$RelayConnectionTask.execute(Client.java:90)
	at nostr.client/nostr.client.Client$RelayConnectionTask.execute(Client.java:1)
	at nostr.util/nostr.util.thread.ThreadUtil.lambda$0(ThreadUtil.java:42)
	... 5 more

abr. 20, 2024 11:03:41 AM nostr.examples.NostrApiExamples main
FINE: ================== The End

I just add a try-catch to ignore this error and now the message "was sent". Actually failed again, but was another cause (the connection wasn't correctly established), the log messages are wrong.

abr. 20, 2024 11:13:16 AM jdk.internal.net.http.HttpClientImpl$SelectorManager run
FINE: [HttpClient-1-SelectorManager] [6s 97ms] HttpClientImpl(1) Next deadline is 3000
abr. 20, 2024 11:13:17 AM nostr.client.Client send
INFO: Sending message EventMessage(super=BaseMessage(command=EVENT), event=GenericEvent(id=5194a2794c82a62199f1f49730c868fceab9ab4c8e65c6c72a235a064b013206, pubKey=7b04bf1e2d0a073294ec43212e6ff9faa53e8fa984fbd5f2c9b876ab2420c7e5, createdAt=1713622389, kind=1, tags=[PubKeyTag(publicKey=a88fe05543c3351d112584a9090c8311c0c21f37ac9d8f96e96a058c3225fba8, mainRelayUrl=null, petName=null)], content=Hello world, I'm here on nostr-java API!, signature=c7ab1a4150a7b20a7ff8b4b4ee0269b43a66fda05bd91e20ffca097d524d0a8b034e58a9dfb94fd4018488643f57ab21a31f72e5e834a9bb3a49be71c2e01040, _serializedEvent=[91, 48, 44, 34, 55, 98, 48, 52, 98, 102, 49, 101, 50, 100, 48, 97, 48, 55, 51, 50, 57, 52, 101, 99, 52, 51, 50, 49, 50, 101, 54, 102, 102, 57, 102, 97, 97, 53, 51, 101, 56, 102, 97, 57, 56, 52, 102, 98, 100, 53, 102, 50, 99, 57, 98, 56, 55, 54, 97, 98, 50, 52, 50, 48, 99, 55, 101, 53, 34, 44, 49, 55, 49, 51, 54, 50, 50, 51, 56, 57, 44, 49, 44, 91, 91, 34, 112, 34, 44, 34, 97, 56, 56, 102, 101, 48, 53, 53, 52, 51, 99, 51, 51, 53, 49, 100, 49, 49, 50, 53, 56, 52, 97, 57, 48, 57, 48, 99, 56, 51, 49, 49, 99, 48, 99, 50, 49, 102, 51, 55, 97, 99, 57, 100, 56, 102, 57, 54, 101, 57, 54, 97, 48, 53, 56, 99, 51, 50, 50, 53, 102, 98, 97, 56, 34, 93, 93, 44, 34, 72, 101, 108, 108, 111, 32, 119, 111, 114, 108, 100, 44, 32, 73, 39, 109, 32, 104, 101, 114, 101, 32, 111, 110, 32, 110, 111, 115, 116, 114, 45, 106, 97, 118, 97, 32, 65, 80, 73, 33, 34, 93], nip=null, attributes=[]), subscriptionId=null)...
abr. 20, 2024 11:13:17 AM nostr.util.thread.ThreadUtil run
FINE: Executing thread on nostr.client.Client$SendMessageTask@61e949f0...
abr. 20, 2024 11:13:17 AM nostr.client.Client$SendMessageTask execute
INFO: +++ Sending message EventMessage(super=BaseMessage(command=EVENT), event=GenericEvent(id=5194a2794c82a62199f1f49730c868fceab9ab4c8e65c6c72a235a064b013206, pubKey=7b04bf1e2d0a073294ec43212e6ff9faa53e8fa984fbd5f2c9b876ab2420c7e5, createdAt=1713622389, kind=1, tags=[PubKeyTag(publicKey=a88fe05543c3351d112584a9090c8311c0c21f37ac9d8f96e96a058c3225fba8, mainRelayUrl=null, petName=null)], content=Hello world, I'm here on nostr-java API!, signature=c7ab1a4150a7b20a7ff8b4b4ee0269b43a66fda05bd91e20ffca097d524d0a8b034e58a9dfb94fd4018488643f57ab21a31f72e5e834a9bb3a49be71c2e01040, _serializedEvent=[91, 48, 44, 34, 55, 98, 48, 52, 98, 102, 49, 101, 50, 100, 48, 97, 48, 55, 51, 50, 57, 52, 101, 99, 52, 51, 50, 49, 50, 101, 54, 102, 102, 57, 102, 97, 97, 53, 51, 101, 56, 102, 97, 57, 56, 52, 102, 98, 100, 53, 102, 50, 99, 57, 98, 56, 55, 54, 97, 98, 50, 52, 50, 48, 99, 55, 101, 53, 34, 44, 49, 55, 49, 51, 54, 50, 50, 51, 56, 57, 44, 49, 44, 91, 91, 34, 112, 34, 44, 34, 97, 56, 56, 102, 101, 48, 53, 53, 52, 51, 99, 51, 51, 53, 49, 100, 49, 49, 50, 53, 56, 52, 97, 57, 48, 57, 48, 99, 56, 51, 49, 49, 99, 48, 99, 50, 49, 102, 51, 55, 97, 99, 57, 100, 56, 102, 57, 54, 101, 57, 54, 97, 48, 53, 56, 99, 51, 50, 50, 53, 102, 98, 97, 56, 34, 93, 93, 44, 34, 72, 101, 108, 108, 111, 32, 119, 111, 114, 108, 100, 44, 32, 73, 39, 109, 32, 104, 101, 114, 101, 32, 111, 110, 32, 110, 111, 115, 116, 114, 45, 106, 97, 118, 97, 32, 65, 80, 73, 33, 34, 93], nip=null, attributes=[]), subscriptionId=null)...
abr. 20, 2024 11:13:17 AM nostr.examples.NostrApiExamples main
FINE: ================== The End
abr. 20, 2024 11:13:18 AM nostr.connection.impl.ConnectionPool send
INFO: >>> Sending ["EVENT",{"id":"5194a2794c82a62199f1f49730c868fceab9ab4c8e65c6c72a235a064b013206","kind":1,"content":"Hello world, I'm here on nostr-java API!","pubkey":"7b04bf1e2d0a073294ec43212e6ff9faa53e8fa984fbd5f2c9b876ab2420c7e5","created_at":1713622389,"tags":[["p","a88fe05543c3351d112584a9090c8311c0c21f37ac9d8f96e96a058c3225fba8"]],"sig":"c7ab1a4150a7b20a7ff8b4b4ee0269b43a66fda05bd91e20ffca097d524d0a8b034e58a9dfb94fd4018488643f57ab21a31f72e5e834a9bb3a49be71c2e01040"}] to 5 relay(s)...
abr. 20, 2024 11:13:18 AM nostr.client.Client$SendMessageTask execute
INFO: OK!
abr. 20, 2024 11:13:19 AM jdk.internal.net.http.HttpClientImpl$SelectorManager run
FINE: [HttpClient-1-SelectorManager] [9s 101ms] HttpClientImpl(1) next timeout: 0
abr. 20, 2024 11:13:19 AM jdk.internal.net.http.HttpClientImpl$SelectorManager run
FINE: [HttpClient-1-SelectorManager] [9s 102ms] HttpClientImpl(1) next expired: 0
abr. 20, 2024 11:13:19 AM jdk.internal.net.http.HttpClientImpl$SelectorManager run

[tcheeric]

@tcheeric

I found a problem with this change, the example of "filters" broke, it's not necessary to sign a request for search events, they are public.

Yes, correct.

[guilhermegps]

@tcheeric
I found a problem with this change, the example of "filters" broke, it's not necessary to sign a request for search events, they are public.

Yes, correct.

So, I will let you check this problem and fix it.

You can test it with this example.

[guilhermegps]

NOW, the Problem I am facing, is that the ServiceLoader is not instantiating the handler classes (See here).

About this problem, I observed that you instanced the listener in ConnectionImpl as an OpenListener, but how the WebSocket will know when call TextListener, CloseListener or whatever? It's not clear for me. I did a test and got success just changing OpenListener to TextListener.

Log:

abr. 21, 2024 12:14:32 PM jdk.internal.net.http.HttpClientImpl$SelectorManager run
FINE: [HttpClient-1-SelectorManager] [15s 778ms] HttpClientImpl(1) Next deadline is 3000
abr. 21, 2024 12:14:34 PM nostr.connection.impl.WebsocketClientListeners$TextListener handleReceivedText
INFO: Received message ["OK","6d83330b8d77b5868589f247015f658da1a95eed93f5d817b486cc9ee07cfa22",true,""] from Relay(uri=nostr.mom)
abr. 21, 2024 12:14:34 PM nostr.connection.impl.WebsocketClientListeners$TextListener handleReceivedText
INFO: Creating the command context with message OkMessage(eventId=6d83330b8d77b5868589f247015f658da1a95eed93f5d817b486cc9ee07cfa22, flag=true, message=)
abr. 21, 2024 12:14:34 PM jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask processText
FINE: [HttpClient-1-Worker-0] [18s 383ms] [WebSocket] exit onText 2 returned java.util.concurrent.CompletableFuture@279f774e[Completed exceptionally: java.util.concurrent.CompletionException: java.lang.NullPointerException: Cannot invoke "nostr.context.impl.DefaultRequestContext.getPrivateKey()" because "this.context" is null]
abr. 21, 2024 12:14:34 PM jdk.internal.net.http.websocket.WebSocketImpl tryChangeState
FINE: [HttpClient-1-Worker-0] [18s 383ms] [WebSocket] change state from TEXT to IDLE true
abr. 21, 2024 12:14:34 PM jdk.internal.net.http.websocket.WebSocketImpl$ReceiveTask run
FINE: [HttpClient-1-Worker-0] [18s 383ms] [WebSocket] receive state: IDLE
abr. 21, 2024 12:14:34 PM jdk.internal.net.http.websocket.WebSocketImpl tryChangeState
FINE: [HttpClient-1-Worker-0] [18s 383ms] [WebSocket] change state from IDLE to WAITING true
abr. 21, 2024 12:14:34 PM jdk.internal.net.http.websocket.TransportImpl request

[guilhermegps]

I observed either that the pool of connection is a little unstable. Maybe it was caused by the timeout, I don't know, but some times no connections are successfully established. We need to analyze carefully this pool and make sure it is under control.

[tcheeric]

@tcheeric
I found a problem with this change, the example of "filters" broke, it's not necessary to sign a request for search events, they are public.

Yes, correct.

So, I will let you check this problem and fix it.

You can test it with this example.

Alright, will do.