add DEBUG logs
This commit is contained in:
parent
0fc26d096f
commit
39f0153f9b
3 changed files with 43 additions and 10 deletions
|
|
@ -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."))
|
||||
|
||||
|
|
|
|||
34
services.py
34
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
|
||||
|
||||
|
|
|
|||
6
tasks.py
6
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)
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue