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

chore: improve logging #130

Merged
merged 6 commits into from
Dec 20, 2024
Merged

chore: improve logging #130

Changes from 1 commit
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
df66787
chore: improve logging
im-adithya Dec 19, 2024
de2d5c5
chore: add subscription uuid to logs
im-adithya Dec 19, 2024
5930f6e
chore: log relay errors only once per app
im-adithya Dec 19, 2024
64fd5e3
chore: log request event id
im-adithya Dec 19, 2024
59c0ab6
Merge pull request #131 from getAlby/task-reconnecting
im-adithya Dec 20, 2024
a415c01
chore: use consistent naming and pass in pointer
im-adithya Dec 20, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
98 changes: 53 additions & 45 deletions internal/nostr/nostr.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -215,7 +215,7 @@ func (svc *Service) InfoHandler(c echo.Context) error {

select {
case <-ctx.Done():
svc.Logger.WithFields(logrus.Fields{
svc.Logger.WithError(ctx.Err()).WithFields(logrus.Fields{
"relay_url": requestData.RelayUrl,
"wallet_pubkey": requestData.WalletPubkey,
}).Error("Exiting info subscription without receiving event")
Expand All @@ -227,7 +227,7 @@ func (svc *Service) InfoHandler(c echo.Context) error {
svc.Logger.WithFields(logrus.Fields{
"relay_url": requestData.RelayUrl,
"wallet_pubkey": requestData.WalletPubkey,
"event_id": event.ID,
"info_event_id": event.ID,
im-adithya marked this conversation as resolved.
Show resolved Hide resolved
}).Info("Received info event")
sub.Unsub()
return c.JSON(http.StatusOK, InfoResponse{
Expand Down Expand Up @@ -370,7 +370,7 @@ func (svc *Service) NIP47Handler(c echo.Context) error {

select {
case <-ctx.Done():
svc.Logger.WithFields(logrus.Fields{
svc.Logger.WithError(ctx.Err()).WithFields(logrus.Fields{
"request_event_id": requestData.SignedEvent.ID,
"client_pubkey": requestData.SignedEvent.PubKey,
"wallet_pubkey": requestData.WalletPubkey,
Expand Down Expand Up @@ -472,14 +472,14 @@ func (svc *Service) NIP47WebhookHandler(c echo.Context) error {
defer cancel()
select {
case <-ctx.Done():
svc.Logger.WithFields(logrus.Fields{
svc.Logger.WithError(ctx.Err()).WithFields(logrus.Fields{
"request_event_id": requestData.SignedEvent.ID,
"client_pubkey": requestData.SignedEvent.PubKey,
"wallet_pubkey": requestData.WalletPubkey,
"relay_url": requestData.RelayUrl,
}).Error("Stopped subscription without receiving event")
case event := <-subscription.EventChan:
svc.postEventToWebhook(event, subscription.WebhookUrl)
svc.postEventToWebhook(event, &subscription)
}
}()

Expand All @@ -490,17 +490,17 @@ func (svc *Service) NIP47WebhookHandler(c echo.Context) error {

func (svc *Service) prepareNIP47Subscription(relayUrl, walletPubkey, webhookUrl string, requestEvent RequestEvent) (Subscription) {
return Subscription{
RelayUrl: relayUrl,
WebhookUrl: webhookUrl,
Open: true,
Authors: &[]string{walletPubkey},
Kinds: &[]int{NIP_47_RESPONSE_KIND},
Tags: &nostr.TagMap{"e": []string{requestEvent.NostrId}},
Since: time.Now(),
Limit: 1,
RequestEvent: &requestEvent,
EventChan: make(chan *nostr.Event, 1),
Uuid: uuid.New().String(),
RelayUrl: relayUrl,
WebhookUrl: webhookUrl,
Open: true,
Authors: &[]string{walletPubkey},
Kinds: &[]int{NIP_47_RESPONSE_KIND},
Tags: &nostr.TagMap{"e": []string{requestEvent.NostrId}},
Since: time.Now(),
Limit: 1,
RequestEvent: &requestEvent,
im-adithya marked this conversation as resolved.
Show resolved Hide resolved
EventChan: make(chan *nostr.Event, 1),
Uuid: uuid.New().String(),
}
}

Expand Down Expand Up @@ -655,13 +655,13 @@ func (svc *Service) StopSubscriptionHandler(c echo.Context) error {
}

svc.Logger.WithFields(logrus.Fields{
"subscription_id": subscription.ID,
"subscription_id": subscription.Uuid,
}).Debug("Stopping subscription")

err := svc.stopSubscription(&subscription)
if err != nil {
svc.Logger.WithFields(logrus.Fields{
"subscription_id": subscription.ID,
"subscription_id": subscription.Uuid,
im-adithya marked this conversation as resolved.
Show resolved Hide resolved
}).Debug("Subscription is stopped already")

return c.JSON(http.StatusAlreadyReported, StopSubscriptionResponse{
Expand All @@ -675,7 +675,7 @@ func (svc *Service) StopSubscriptionHandler(c echo.Context) error {
// delete svix app

svc.Logger.WithFields(logrus.Fields{
"subscription_id": subscription.ID,
"subscription_id": subscription.Uuid,
}).Info("Stopped subscription")

return c.JSON(http.StatusOK, StopSubscriptionResponse{
Expand All @@ -702,7 +702,7 @@ func (svc *Service) stopSubscription(subscription *Subscription) error {

func (svc *Service) startSubscription(ctx context.Context, subscription *Subscription, onReceiveEOS OnReceiveEOSFunc, handleEvent HandleEventFunc) {
svc.Logger.WithFields(logrus.Fields{
"subscription_id": subscription.ID,
"subscription_id": subscription.Uuid,
"relay_url": subscription.RelayUrl,
}).Debug("Starting subscription")

Expand All @@ -719,8 +719,8 @@ func (svc *Service) startSubscription(ctx context.Context, subscription *Subscri
relay.Close()
}
if ctx.Err() != nil {
svc.Logger.WithFields(logrus.Fields{
"subscription_id": subscription.ID,
svc.Logger.WithError(ctx.Err()).WithFields(logrus.Fields{
"subscription_id": subscription.Uuid,
"relay_url": subscription.RelayUrl,
}).Debug("Context canceled, stopping subscription")
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we really want to change this to error level?

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think so - I don't think we want to receive context cancelled errors, do we? I guess this means a hub is offline and we cannot do anything, but it's something that is good to know. Maybe getalby.com eventually should stop trying to request to offline hubs CC @bumi ?

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

And before we did not know for certain it's a context cancelled error. Before we just assume it is. I think therefore the message should also be changed. It should not say Context canceled,

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

True, I was thinking from one-off susbcriptions pov where this might be hit because of timeout, thereby causing bloat, will address this too in the one-off separation PR 👍

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Leaving this as Error level for now (the separated one-off subscription function will have debug log)

Copy link

@rolznz rolznz Dec 20, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@im-adithya

where this might be hit because of timeout

I still think that we should know this is happening and not just hide it? I still think we need to solve the root problem.

svc.stopSubscription(subscription)
Expand All @@ -733,7 +733,7 @@ func (svc *Service) startSubscription(ctx context.Context, subscription *Subscri
waitToReconnectSeconds = max(waitToReconnectSeconds, 1)
waitToReconnectSeconds = min(waitToReconnectSeconds * 2, 900)
svc.Logger.WithError(err).WithFields(logrus.Fields{
"subscription_id": subscription.ID,
"subscription_id": subscription.Uuid,
"relay_url": subscription.RelayUrl,
}).Errorf("Failed to connect to relay, retrying in %vs...", waitToReconnectSeconds)
continue
Expand All @@ -745,7 +745,7 @@ func (svc *Service) startSubscription(ctx context.Context, subscription *Subscri
waitToReconnectSeconds = max(waitToReconnectSeconds, 1)
waitToReconnectSeconds = min(waitToReconnectSeconds * 2, 900)
svc.Logger.WithError(err).WithFields(logrus.Fields{
"subscription_id": subscription.ID,
"subscription_id": subscription.Uuid,
"relay_url": subscription.RelayUrl,
}).Errorf("Failed to subscribe to relay, retrying in %vs...", waitToReconnectSeconds)
continue
Expand All @@ -756,7 +756,7 @@ func (svc *Service) startSubscription(ctx context.Context, subscription *Subscri
svc.subscriptionsMutex.Unlock()

svc.Logger.WithFields(logrus.Fields{
"subscription_id": subscription.ID,
"subscription_id": subscription.Uuid,
"relay_url": subscription.RelayUrl,
}).Debug("Started subscription")

Expand All @@ -767,7 +767,7 @@ func (svc *Service) startSubscription(ctx context.Context, subscription *Subscri
if err != nil {
// TODO: notify user about subscription failure
svc.Logger.WithError(err).WithFields(logrus.Fields{
"subscription_id": subscription.ID,
"subscription_id": subscription.Uuid,
"relay_url": subscription.RelayUrl,
}).Error("Subscription stopped due to relay error, reconnecting...")
continue
Expand All @@ -778,7 +778,7 @@ func (svc *Service) startSubscription(ctx context.Context, subscription *Subscri
// stop the subscription if it's an NIP47 request
if (subscription.RequestEvent != nil) {
svc.Logger.WithFields(logrus.Fields{
"subscription_id": subscription.ID,
"subscription_id": subscription.Uuid,
"relay_url": subscription.RelayUrl,
}).Debug("Stopping subscription")
svc.stopSubscription(subscription)
Expand Down Expand Up @@ -844,10 +844,10 @@ func (svc *Service) handleResponseEvent(event *nostr.Event, subscription *Subscr

func (svc *Service) handleSubscribedEvent(event *nostr.Event, subscription *Subscription) {
svc.Logger.WithFields(logrus.Fields{
"event_id": event.ID,
"event_kind": event.Kind,
"subscription_id": subscription.ID,
"relay_url": subscription.RelayUrl,
"response_event_id": event.ID,
"response_event_kind": event.Kind,
"subscription_id": subscription.Uuid,
"relay_url": subscription.RelayUrl,
}).Info("Received subscribed event")
responseEvent := ResponseEvent{
NostrId: event.ID,
Expand All @@ -856,7 +856,7 @@ func (svc *Service) handleSubscribedEvent(event *nostr.Event, subscription *Subs
SubscriptionId: &subscription.ID,
}
svc.db.Save(&responseEvent)
svc.postEventToWebhook(event, subscription.WebhookUrl)
svc.postEventToWebhook(event, subscription)
}

func (svc *Service) processEvents(ctx context.Context, subscription *Subscription, onReceiveEOS OnReceiveEOSFunc, handleEvent HandleEventFunc) error {
Expand All @@ -868,7 +868,7 @@ func (svc *Service) processEvents(ctx context.Context, subscription *Subscriptio
// block till EOS is received
<-sub.EndOfStoredEvents
svc.Logger.WithFields(logrus.Fields{
"subscription_id": subscription.ID,
"subscription_id": subscription.Uuid,
"relay_url": subscription.RelayUrl,
}).Debug("Received EOS")

Expand All @@ -882,7 +882,7 @@ func (svc *Service) processEvents(ctx context.Context, subscription *Subscriptio
}

svc.Logger.WithFields(logrus.Fields{
"subscription_id": subscription.ID,
"subscription_id": subscription.Uuid,
"relay_url": subscription.RelayUrl,
}).Debug("Relay subscription events channel ended")
}()
Expand Down Expand Up @@ -921,32 +921,40 @@ func (svc *Service) getRelayConnection(ctx context.Context, customRelayURL strin
}
}

func (svc *Service) postEventToWebhook(event *nostr.Event, webhookURL string) {
func (svc *Service) postEventToWebhook(event *nostr.Event, subscription *Subscription) {
eventData, err := json.Marshal(event)
request_event_id := ""
if subscription.RequestEvent != nil {
request_event_id = subscription.RequestEvent.NostrId
}

if err != nil {
svc.Logger.WithError(err).WithFields(logrus.Fields{
"event_id": event.ID,
"event_kind": event.Kind,
"webhook_url": webhookURL,
"request_event_id": request_event_id,
"response_event_id": event.ID,
"response_event_kind": event.Kind,
"webhook_url": subscription.WebhookUrl,
}).Error("Failed to marshal event for webhook")
return
}

// TODO: add svix functionality
_, err = http.Post(webhookURL, "application/json", bytes.NewBuffer(eventData))
_, err = http.Post(subscription.WebhookUrl, "application/json", bytes.NewBuffer(eventData))
if err != nil {
svc.Logger.WithError(err).WithFields(logrus.Fields{
"event_id": event.ID,
"event_kind": event.Kind,
"webhook_url": webhookURL,
"request_event_id": request_event_id,
"response_event_id": event.ID,
"response_event_kind": event.Kind,
"webhook_url": subscription.WebhookUrl,
}).Error("Failed to post event to webhook")
return
}

svc.Logger.WithFields(logrus.Fields{
"event_id": event.ID,
"event_kind": event.Kind,
"webhook_url": webhookURL,
"request_event_id": request_event_id,
"response_event_id": event.ID,
"response_event_kind": event.Kind,
"webhook_url": subscription.WebhookUrl,
}).Info("Posted event to webhook")
}

Expand Down
Loading