diff --git a/nostr/nostr_client.py b/nostr/nostr_client.py index 5e902e4..96c37fb 100644 --- a/nostr/nostr_client.py +++ b/nostr/nostr_client.py @@ -91,9 +91,11 @@ class NostrClient: self.subscription_id = "nostrmarket-" + urlsafe_short_hash()[:32] await self.send_req_queue.put(["REQ", self.subscription_id] + merchant_filters) - logger.debug( - f"Subscribing to events for: {len(public_keys)} keys. New subscription id: {self.subscription_id}" + logger.info( + f"[NOSTRMARKET DEBUG] Subscribing to events for: {len(public_keys)} keys. New subscription id: {self.subscription_id}" ) + logger.info(f"[NOSTRMARKET DEBUG] Subscription filters: {merchant_filters}") + logger.info(f"[NOSTRMARKET DEBUG] Public keys: {public_keys}") async def merchant_temp_subscription(self, pk, duration=10): dm_filters = self._filters_for_direct_messages([pk], 0) @@ -175,16 +177,17 @@ class NostrClient: def _ws_handlers(self): def on_open(_): - logger.info("Connected to 'nostrclient' websocket") + logger.info("[NOSTRMARKET DEBUG] Connected to 'nostrclient' websocket") def on_message(_, message): + logger.info(f"[NOSTRMARKET DEBUG] Received websocket message: {message[:200]}...") self.recieve_event_queue.put_nowait(message) def on_error(_, error): - logger.warning(error) + logger.warning(f"[NOSTRMARKET DEBUG] Websocket error: {error}") def on_close(x, status_code, message): - logger.warning(f"Websocket closed: {x}: '{status_code}' '{message}'") + logger.warning(f"[NOSTRMARKET DEBUG] Websocket closed: {x}: '{status_code}' '{message}'") # force re-subscribe self.recieve_event_queue.put_nowait(ValueError("Websocket close.")) diff --git a/services.py b/services.py index a9b32ed..4c65e38 100644 --- a/services.py +++ b/services.py @@ -314,24 +314,32 @@ async def compute_products_new_quantity( async def process_nostr_message(msg: str): + logger.info(f"[NOSTRMARKET DEBUG] Received nostr message: {msg[:200]}...") try: type_, *rest = json.loads(msg) if type_.upper() == "EVENT": _, event = rest event = NostrEvent(**event) + logger.info(f"[NOSTRMARKET DEBUG] Processing event - kind: {event.kind}, id: {event.id}, pubkey: {event.pubkey}") if event.kind == 0: + logger.info(f"[NOSTRMARKET DEBUG] Handling customer profile update - event: {event.id}") await _handle_customer_profile_update(event) elif event.kind == 4: + logger.info(f"[NOSTRMARKET DEBUG] Handling NIP04 message - event: {event.id}, from: {event.pubkey}, content_length: {len(event.content)}") await _handle_nip04_message(event) elif event.kind == 30017: + logger.info(f"[NOSTRMARKET DEBUG] Handling stall event - event: {event.id}") await _handle_stall(event) elif event.kind == 30018: + logger.info(f"[NOSTRMARKET DEBUG] Handling product event - event: {event.id}") await _handle_product(event) + else: + logger.info(f"[NOSTRMARKET DEBUG] Unhandled event kind: {event.kind} - event: {event.id}") return except Exception as ex: - logger.debug(ex) + logger.error(f"[NOSTRMARKET DEBUG] Error processing nostr message: {ex}") async def create_or_update_order_from_dm( @@ -413,40 +421,53 @@ async def extract_customer_order_from_dm( async def _handle_nip04_message(event: NostrEvent): + logger.info(f"[NOSTRMARKET DEBUG] _handle_nip04_message - event: {event.id}, from: {event.pubkey}, tags: {event.tags}") merchant_public_key = event.pubkey merchant = await get_merchant_by_pubkey(merchant_public_key) + logger.info(f"[NOSTRMARKET DEBUG] Looking for merchant by pubkey {merchant_public_key}, found: {merchant is not None}") if not merchant: p_tags = event.tag_values("p") + logger.info(f"[NOSTRMARKET DEBUG] No merchant found for sender, checking p_tags: {p_tags}") if len(p_tags) and p_tags[0]: merchant_public_key = p_tags[0] merchant = await get_merchant_by_pubkey(merchant_public_key) + logger.info(f"[NOSTRMARKET DEBUG] Looking for merchant by p_tag {merchant_public_key}, found: {merchant is not None}") assert merchant, f"Merchant not found for public key '{merchant_public_key}'" if event.pubkey == merchant_public_key: + logger.info(f"[NOSTRMARKET DEBUG] Processing outgoing message from merchant {merchant_public_key}") assert len(event.tag_values("p")) != 0, "Outgong message has no 'p' tag" clear_text_msg = merchant.decrypt_message( event.content, event.tag_values("p")[0] ) + logger.info(f"[NOSTRMARKET DEBUG] Decrypted outgoing message: {clear_text_msg[:100]}...") await _handle_outgoing_dms(event, merchant, clear_text_msg) elif event.has_tag_value("p", merchant_public_key): + logger.info(f"[NOSTRMARKET DEBUG] Processing incoming message to merchant {merchant_public_key} from {event.pubkey}") clear_text_msg = merchant.decrypt_message(event.content, event.pubkey) + logger.info(f"[NOSTRMARKET DEBUG] Decrypted incoming message: {clear_text_msg[:100]}...") await _handle_incoming_dms(event, merchant, clear_text_msg) else: - logger.warning(f"Bad NIP04 event: '{event.id}'") + logger.warning(f"[NOSTRMARKET DEBUG] Bad NIP04 event: '{event.id}' - pubkey: {event.pubkey}, merchant: {merchant_public_key}") async def _handle_incoming_dms( event: NostrEvent, merchant: Merchant, clear_text_msg: str ): + logger.info(f"[NOSTRMARKET DEBUG] _handle_incoming_dms - merchant: {merchant.id}, customer: {event.pubkey}") customer = await get_customer(merchant.id, event.pubkey) if not customer: + logger.info(f"[NOSTRMARKET DEBUG] Creating new customer for pubkey: {event.pubkey}") await _handle_new_customer(event, merchant) else: + logger.info(f"[NOSTRMARKET DEBUG] Existing customer found, incrementing unread messages") await increment_customer_unread_messages(merchant.id, event.pubkey) + logger.info(f"[NOSTRMARKET DEBUG] Parsing message: {clear_text_msg}") dm_type, json_data = PartialDirectMessage.parse_message(clear_text_msg) + logger.info(f"[NOSTRMARKET DEBUG] Parsed message - type: {dm_type}, has_json_data: {json_data is not None}") new_dm = await _persist_dm( merchant.id, dm_type.value, @@ -485,16 +506,21 @@ async def _handle_outgoing_dms( async def _handle_incoming_structured_dm( merchant: Merchant, dm: DirectMessage, json_data: dict ) -> Tuple[DirectMessageType, Optional[str]]: + logger.info(f"[NOSTRMARKET DEBUG] _handle_incoming_structured_dm - merchant: {merchant.id}, dm_type: {dm.type}, merchant_active: {merchant.config.active}") + logger.info(f"[NOSTRMARKET DEBUG] JSON data: {json_data}") try: if dm.type == DirectMessageType.CUSTOMER_ORDER.value and merchant.config.active: + logger.info(f"[NOSTRMARKET DEBUG] Processing CUSTOMER_ORDER for merchant {merchant.id}") json_resp = await _handle_new_order( merchant.id, merchant.public_key, dm, json_data ) - + logger.info(f"[NOSTRMARKET DEBUG] New order processed, response: {json_resp[:100] if json_resp else None}...") return DirectMessageType.PAYMENT_REQUEST, json_resp + else: + logger.info(f"[NOSTRMARKET DEBUG] Skipping order processing - type: {dm.type}, expected: {DirectMessageType.CUSTOMER_ORDER.value}, merchant_active: {merchant.config.active}") except Exception as ex: - logger.warning(ex) + logger.error(f"[NOSTRMARKET DEBUG] Error in _handle_incoming_structured_dm: {ex}") return DirectMessageType.PLAIN_TEXT, None diff --git a/tasks.py b/tasks.py index 013a281..774951f 100644 --- a/tasks.py +++ b/tasks.py @@ -35,13 +35,17 @@ async def on_invoice_paid(payment: Payment) -> None: async def wait_for_nostr_events(nostr_client: NostrClient): + logger.info("[NOSTRMARKET DEBUG] Starting wait_for_nostr_events task") while True: try: + logger.info("[NOSTRMARKET DEBUG] Subscribing to all merchants...") await subscribe_to_all_merchants() while True: + logger.debug("[NOSTRMARKET DEBUG] Waiting for nostr event...") message = await nostr_client.get_event() + logger.info(f"[NOSTRMARKET DEBUG] Received event from nostr_client: {message[:100]}...") await process_nostr_message(message) except Exception as e: - logger.warning(f"Subcription failed. Will retry in one minute: {e}") + logger.warning(f"[NOSTRMARKET DEBUG] Subscription failed. Will retry in 10 seconds: {e}") await asyncio.sleep(10)