Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ServiceLoader is not instantiating the command handler classes #147

Closed
tcheeric opened this issue Apr 17, 2024 · 12 comments
Closed

ServiceLoader is not instantiating the command handler classes #147

tcheeric opened this issue Apr 17, 2024 · 12 comments
Assignees
@tcheeric @guilhermegps
Labels
bug Something isn't working Done! Completed the implementation. May require more testing. help wanted Extra attention is needed

Comments

@tcheeric
Copy link
Owner

@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!
@tcheeric tcheeric added bug Something isn't working help wanted Extra attention is needed labels Apr 17, 2024
@guilhermegps
Copy link
Collaborator

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

@guilhermegps
Copy link
Collaborator

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
Copy link
Owner Author

tcheeric commented Apr 19, 2024 •
edited

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
Copy link
Collaborator

@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
Copy link
Collaborator

guilhermegps commented Apr 20, 2024 •
edited

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
Copy link
Owner Author

@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
Copy link
Collaborator

@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
Copy link
Collaborator

guilhermegps commented Apr 21, 2024 •
edited

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
Copy link
Collaborator

guilhermegps commented Apr 21, 2024 •
edited

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.

@guilhermegps guilhermegps mentioned this issue Apr 21, 2024
Merged
@tcheeric
Copy link
Owner Author

@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
Copy link
Owner Author

tcheeric commented Apr 21, 2024 •
edited

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
Copy link
Owner Author

I have finally found the issue with the ServiceLoader!

@tcheeric tcheeric added the Done! Completed the implementation. May require more testing. label Apr 23, 2024
tcheeric pushed a commit that referenced this issue Apr 24, 2024
fix #147
b5b39f9
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@tcheeric tcheeric

@guilhermegps guilhermegps

Labels
bug Something isn't working Done! Completed the implementation. May require more testing. help wanted Extra attention is needed
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@tcheeric @guilhermegps