search

tcheeric / nostr-java

A nostr library, written in java, for generating, signing and publishing events.
MIT License
71 stars 23 forks source link

ServiceLoader is not instantiating the command handler classes #147

Closed tcheeric closed 7 months ago

tcheeric commented 7 months ago

@guilhermegps

While trying to implement NIP-42, I noticed some limitations with the current code.

NIP-42 expects the client to reply with a signed auth event when receiving an AUTH-message from a relay. Currently, this takes place in the onAuth method here.

However, to sign the event, you need to have access to the private key, which is not available in that class at the moment.

I have therefore introduced the concept of Context classes, where I store contextual information, including the private key. The context is created in the api module when instantiating a client object, passed along to the other modules, and is now available in the OnAuth command handler.

Additional major changes (Branch 0.6-SNAPSHOT):

  1. I noticed that for every request to a relay, we would open a new connection. This is not good. I have now created a ConnectionPool to keep track of the connections, and ensure that we only have one connection per relay.
  2. One other change I have made is that I now have, for each relay command, e.g. Ok, Eose, Auth, Closed etc, a separate handler class, instead of a unique command handler class with a method for each command.
  3. You will notice I have also renamed, added, removed a few modules. Hopefully this is more intuitive and cleaner.
  4. etc.

I welcome your opinions and suggestions on this.

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

I need a second pair of eyes to review and hopefully find what is missing, and why it's not working.

Could you please have a look when you have a moment?

Thanks!

guilhermegps commented 7 months ago

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

guilhermegps commented 7 months ago

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

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

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

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

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

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

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

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

@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.

tcheeric commented 7 months ago

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.)

tcheeric commented 7 months ago

I have finally found the issue with the ServiceLoader!