Duplicate entry error when using cln + postgres + bolt11 #1162

Closed
opened 2025-10-07 12:33:51 +00:00 by daywalker90 · 7 comments
daywalker90 commented 2025-10-07 12:33:51 +00:00 (Migrated from github.com)

I'm trying cdk-mintd @ main with my CLN v25.09 node and cdk-cli. I tried to mint some sats but i always get a duplicate entry error. First i thought it was because i paid the bolt11 with a self payment but it happens with an external wallet aswell.

Using --method bolt12 works fine, the only thing weird was that the command didn't return but Ctrl+C and checking the balance showed that it was there.

Full log of mintd when the payment happens:

2025-10-07T12:16:24.170332Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Received response from WaitAnyInvoice call
2025-10-07T12:16:24.170349Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Successfully received invoice data
2025-10-07T12:16:24.170358Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Parsed WaitAnyInvoice response successfully
2025-10-07T12:16:24.170364Z  INFO wait_for_processor_payments: cdk_cln: CLN: Invoice with payment index 4292 is PAID
2025-10-07T12:16:24.170371Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Updated last_pay_idx to Some(4292)
2025-10-07T12:16:24.170393Z DEBUG wait_for_processor_payments: tokio_postgres::prepare: preparing query s46: START TRANSACTION
2025-10-07T12:16:24.170508Z DEBUG wait_for_processor_payments: tokio_postgres::query: executing statement s46 with parameters: []
2025-10-07T12:16:24.170679Z DEBUG wait_for_processor_payments: tokio_postgres::prepare: preparing query s47: INSERT INTO kv_store
            (primary_namespace, secondary_namespace, key, value, created_time, updated_time)
            VALUES ( $1 , $2 , $3 , $4 , $5 , $6 )
            ON CONFLICT(primary_namespace, secondary_namespace, key)
            DO UPDATE SET
                value = excluded.value,
                updated_time = excluded.updated_time
2025-10-07T12:16:24.170850Z DEBUG wait_for_processor_payments: tokio_postgres::query: executing statement s47 with parameters: [Text("cdk_cln_lightning_backend"), Text("payment_indices"), Text("last_pay_index"), Blob([52, 50, 57, 50]), Integer(1759839384), Integer(1759839384)]
2025-10-07T12:16:24.171036Z DEBUG wait_for_processor_payments: tokio_postgres::prepare: preparing query s48: COMMIT
2025-10-07T12:16:24.171123Z DEBUG wait_for_processor_payments: tokio_postgres::query: executing statement s48 with parameters: []
2025-10-07T12:16:24.193324Z  WARN wait_for_processor_payments: cdk_sql_common::common: [SLOW QUERY] Took 22 ms: COMMIT
2025-10-07T12:16:24.193340Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Stored last pay index 4292 in KV store
2025-10-07T12:16:24.193345Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Payment hash: 81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b
2025-10-07T12:16:24.193350Z  INFO wait_for_processor_payments: cdk_cln: CLN: Received payment of 1000 msats for 81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b
2025-10-07T12:16:24.193363Z  INFO wait_for_processor_payments: cdk_cln: CLN: Processing BOLT11 payment with hash 81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b
2025-10-07T12:16:24.193372Z  INFO wait_for_processor_payments: cdk_cln: CLN: Created WaitPaymentResponse with amount 1000 msats
2025-10-07T12:16:24.193391Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::prepare: preparing query s49: START TRANSACTION
2025-10-07T12:16:24.193470Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::query: executing statement s49 with parameters: []
2025-10-07T12:16:24.193550Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::prepare: preparing query s50: SELECT
                id,
                amount,
                unit,
                request,
                expiry,
                request_lookup_id,
                pubkey,
                created_time,
                amount_paid,
                amount_issued,
                payment_method,
                request_lookup_id_kind
            FROM
                mint_quote
            WHERE request_lookup_id = $1 AND request_lookup_id_kind = $2 FOR UPDATE
2025-10-07T12:16:24.193677Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::query: executing statement s50 with parameters: [Text("81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"), Text("payment_hash")]
2025-10-07T12:16:24.193882Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::prepare: preparing query s51: SELECT
            payment_id,
            timestamp,
            amount
        FROM
            mint_quote_payments
        WHERE
            quote_id= $1
2025-10-07T12:16:24.194020Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::query: executing statement s51 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")]
2025-10-07T12:16:24.194151Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::prepare: preparing query s52: SELECT amount, timestamp
FROM mint_quote_issued
WHERE quote_id= $1
2025-10-07T12:16:24.194229Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::query: executing statement s52 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")]
2025-10-07T12:16:24.194318Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment: cdk::mint: Received payment notification of 1000 msat for mint quote 44633f4e-8c1f-4ed0-877a-e4d479f33cf5 with payment id 81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b
2025-10-07T12:16:24.194331Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment: cdk::mint: Payment received amount in quote unit sat 1
2025-10-07T12:16:24.194355Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s53: SELECT payment_id
            FROM mint_quote_payments
            WHERE payment_id = $1 FOR UPDATE
2025-10-07T12:16:24.194433Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s53 with parameters: [Text("81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b")]
2025-10-07T12:16:24.194537Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s54: SELECT amount_paid
            FROM mint_quote
            WHERE id = $1 FOR UPDATE
2025-10-07T12:16:24.194594Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s54 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")]
2025-10-07T12:16:24.194672Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: cdk_sql_common::mint: Mint quote 44633f4e-8c1f-4ed0-877a-e4d479f33cf5 amount paid was 0 is now 1.
2025-10-07T12:16:24.194683Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s55: UPDATE mint_quote
            SET amount_paid = $1 WHERE id = $2
2025-10-07T12:16:24.194736Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s55 with parameters: [Integer(1), Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")]
2025-10-07T12:16:24.194887Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s56: INSERT INTO mint_quote_payments
            (quote_id, payment_id, amount, timestamp)
            VALUES ( $1 , $2 , $3 , $4 )
2025-10-07T12:16:24.194954Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s56 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5"), Text("81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"), Integer(1), Integer(1759839384)]
2025-10-07T12:16:24.195218Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::prepare: preparing query s57: COMMIT
2025-10-07T12:16:24.195277Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::query: executing statement s57 with parameters: []
2025-10-07T12:16:24.198507Z DEBUG get_mint_info:mint_info: tokio_postgres::prepare: preparing query s58: SELECT value
            FROM kv_store
            WHERE primary_namespace = $1 AND secondary_namespace = $2 AND key = $3
2025-10-07T12:16:24.199036Z DEBUG get_mint_info:mint_info: tokio_postgres::query: executing statement s58 with parameters: [Text("cdk_mint"), Text("config"), Text("mint_info")]
2025-10-07T12:16:24.200738Z DEBUG get_mint_info:mint_info: tokio_postgres::prepare: preparing query s59: SELECT value
            FROM kv_store
            WHERE primary_namespace = $1 AND secondary_namespace = $2 AND key = $3
2025-10-07T12:16:24.200808Z DEBUG get_mint_info:mint_info: tokio_postgres::query: executing statement s59 with parameters: [Text("cdk_mint"), Text("config"), Text("mint_info")]
2025-10-07T12:16:24.202064Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::prepare: preparing query s60: SELECT
            payment_id,
            timestamp,
            amount
        FROM
            mint_quote_payments
        WHERE
            quote_id= $1
2025-10-07T12:16:24.202239Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::query: executing statement s60 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")]
2025-10-07T12:16:24.202431Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::prepare: preparing query s61: SELECT amount, timestamp
FROM mint_quote_issued
WHERE quote_id= $1
2025-10-07T12:16:24.202518Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::query: executing statement s61 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")]
2025-10-07T12:16:24.202639Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::prepare: preparing query s62: SELECT
                    id,
                    amount,
                    unit,
                    request,
                    expiry,
                    request_lookup_id,
                    pubkey,
                    created_time,
                    amount_paid,
                    amount_issued,
                    payment_method,
                    request_lookup_id_kind
                FROM
                    mint_quote
                WHERE id = $1
2025-10-07T12:16:24.202755Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::query: executing statement s62 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")]
2025-10-07T12:16:24.202985Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:check_incoming_payment_status{payment_identifier=PaymentHash([129, 97, 145, 57, 32, 95, 21, 253, 30, 10, 60, 225, 28, 106, 58, 144, 3, 36, 39, 101, 77, 235, 100, 45, 50, 58, 230, 118, 186, 138, 127, 59])}: cln_rpc: Connecting to socket at /home/bitcoin/.lightning/bitcoin/lightning-rpc
2025-10-07T12:16:24.203758Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid: tokio_postgres::prepare: preparing query s63: START TRANSACTION
2025-10-07T12:16:24.203807Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid: tokio_postgres::query: executing statement s63 with parameters: []
2025-10-07T12:16:24.203843Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid: cdk::mint::ln: Found payment of 1000 msat for quote 44633f4e-8c1f-4ed0-877a-e4d479f33cf5 when checking.
2025-10-07T12:16:24.203861Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s64: SELECT payment_id
            FROM mint_quote_payments
            WHERE payment_id = $1 FOR UPDATE
2025-10-07T12:16:24.203925Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s64 with parameters: [Text("81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b")]
2025-10-07T12:16:24.204011Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s65: SELECT amount_paid
            FROM mint_quote
            WHERE id = $1 FOR UPDATE
2025-10-07T12:16:24.204069Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s65 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")]
2025-10-07T12:16:24.219711Z  WARN wait_for_processor_payments:handle_payment_notification: cdk_sql_common::common: [SLOW QUERY] Took 24 ms: COMMIT
2025-10-07T12:16:24.219725Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Stream is now active, waiting for invoice events with lastpay_index: Some(4292)
2025-10-07T12:16:24.219766Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: cdk_sql_common::mint: Mint quote 44633f4e-8c1f-4ed0-877a-e4d479f33cf5 amount paid was 1 is now 2.
2025-10-07T12:16:24.219779Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s66: UPDATE mint_quote
            SET amount_paid = $1 WHERE id = $2
2025-10-07T12:16:24.219871Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s66 with parameters: [Integer(2), Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")]
2025-10-07T12:16:24.220163Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s67: INSERT INTO mint_quote_payments
            (quote_id, payment_id, amount, timestamp)
            VALUES ( $1 , $2 , $3 , $4 )
2025-10-07T12:16:24.220267Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s67 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5"), Text("81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"), Integer(1), Integer(1759839384)]
2025-10-07T12:16:24.220503Z ERROR post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: cdk_sql_common::common: Query INSERT INTO mint_quote_payments
            (quote_id, payment_id, amount, timestamp)
            VALUES ( $1 , $2 , $3 , $4 ) failed with error Error { kind: Db, cause: Some(DbError { severity: "ERROR", parsed_severity: Some(Error), code: SqlState(E23505), message: "duplicate key value violates unique constraint \"mint_quote_payments_payment_id_key\"", detail: Some("Key (payment_id)=(81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b) already exists."), hint: None, position: None, where_: None, schema: Some("public"), table: Some("mint_quote_payments"), column: None, datatype: None, constraint: Some("mint_quote_payments_payment_id_key"), file: Some("nbtinsert.c"), line: Some(666), routine: Some("_bt_check_unique") }) }
2025-10-07T12:16:24.220528Z ERROR post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: cdk_sql_common::mint: SQLite could not insert payment ID: Duplicate entry
2025-10-07T12:16:24.220544Z ERROR post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}: cdk_axum::router_handlers: Could not process mint: Duplicate entry
2025-10-07T12:16:24.220564Z ERROR tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=18 ms
2025-10-07T12:16:24.220618Z DEBUG tokio_postgres::prepare: preparing query s68: ROLLBACK
2025-10-07T12:16:24.220663Z DEBUG tokio_postgres::query: executing statement s68 with parameters: []
2025-10-07T12:16:24.220825Z DEBUG tungstenite::protocol: Received close frame: None
2025-10-07T12:16:24.220832Z DEBUG tungstenite::protocol: Replying to close with Frame { header: FrameHeader { is_final: true, rsv1: false, rsv2: false, rsv3: false, opcode: Control(Close), mask: None }, payload: b"" }
2025-10-07T12:16:24.220839Z  INFO cdk_axum::ws: ws-close: no frame
2025-10-07T12:16:24.220845Z DEBUG tokio_tungstenite: websocket start_send error: WebSocket protocol error: Sending after closing is not allowed
I'm trying cdk-mintd @ main with my CLN v25.09 node and cdk-cli. I tried to `mint` some sats but i always get a duplicate entry error. First i thought it was because i paid the bolt11 with a self payment but it happens with an external wallet aswell. Using `--method bolt12` works fine, the only thing weird was that the command didn't return but Ctrl+C and checking the `balance` showed that it was there. Full log of mintd when the payment happens: ``` 2025-10-07T12:16:24.170332Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Received response from WaitAnyInvoice call 2025-10-07T12:16:24.170349Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Successfully received invoice data 2025-10-07T12:16:24.170358Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Parsed WaitAnyInvoice response successfully 2025-10-07T12:16:24.170364Z INFO wait_for_processor_payments: cdk_cln: CLN: Invoice with payment index 4292 is PAID 2025-10-07T12:16:24.170371Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Updated last_pay_idx to Some(4292) 2025-10-07T12:16:24.170393Z DEBUG wait_for_processor_payments: tokio_postgres::prepare: preparing query s46: START TRANSACTION 2025-10-07T12:16:24.170508Z DEBUG wait_for_processor_payments: tokio_postgres::query: executing statement s46 with parameters: [] 2025-10-07T12:16:24.170679Z DEBUG wait_for_processor_payments: tokio_postgres::prepare: preparing query s47: INSERT INTO kv_store (primary_namespace, secondary_namespace, key, value, created_time, updated_time) VALUES ( $1 , $2 , $3 , $4 , $5 , $6 ) ON CONFLICT(primary_namespace, secondary_namespace, key) DO UPDATE SET value = excluded.value, updated_time = excluded.updated_time 2025-10-07T12:16:24.170850Z DEBUG wait_for_processor_payments: tokio_postgres::query: executing statement s47 with parameters: [Text("cdk_cln_lightning_backend"), Text("payment_indices"), Text("last_pay_index"), Blob([52, 50, 57, 50]), Integer(1759839384), Integer(1759839384)] 2025-10-07T12:16:24.171036Z DEBUG wait_for_processor_payments: tokio_postgres::prepare: preparing query s48: COMMIT 2025-10-07T12:16:24.171123Z DEBUG wait_for_processor_payments: tokio_postgres::query: executing statement s48 with parameters: [] 2025-10-07T12:16:24.193324Z WARN wait_for_processor_payments: cdk_sql_common::common: [SLOW QUERY] Took 22 ms: COMMIT 2025-10-07T12:16:24.193340Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Stored last pay index 4292 in KV store 2025-10-07T12:16:24.193345Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Payment hash: 81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b 2025-10-07T12:16:24.193350Z INFO wait_for_processor_payments: cdk_cln: CLN: Received payment of 1000 msats for 81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b 2025-10-07T12:16:24.193363Z INFO wait_for_processor_payments: cdk_cln: CLN: Processing BOLT11 payment with hash 81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b 2025-10-07T12:16:24.193372Z INFO wait_for_processor_payments: cdk_cln: CLN: Created WaitPaymentResponse with amount 1000 msats 2025-10-07T12:16:24.193391Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::prepare: preparing query s49: START TRANSACTION 2025-10-07T12:16:24.193470Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::query: executing statement s49 with parameters: [] 2025-10-07T12:16:24.193550Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::prepare: preparing query s50: SELECT id, amount, unit, request, expiry, request_lookup_id, pubkey, created_time, amount_paid, amount_issued, payment_method, request_lookup_id_kind FROM mint_quote WHERE request_lookup_id = $1 AND request_lookup_id_kind = $2 FOR UPDATE 2025-10-07T12:16:24.193677Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::query: executing statement s50 with parameters: [Text("81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"), Text("payment_hash")] 2025-10-07T12:16:24.193882Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::prepare: preparing query s51: SELECT payment_id, timestamp, amount FROM mint_quote_payments WHERE quote_id= $1 2025-10-07T12:16:24.194020Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::query: executing statement s51 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")] 2025-10-07T12:16:24.194151Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::prepare: preparing query s52: SELECT amount, timestamp FROM mint_quote_issued WHERE quote_id= $1 2025-10-07T12:16:24.194229Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::query: executing statement s52 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")] 2025-10-07T12:16:24.194318Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment: cdk::mint: Received payment notification of 1000 msat for mint quote 44633f4e-8c1f-4ed0-877a-e4d479f33cf5 with payment id 81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b 2025-10-07T12:16:24.194331Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment: cdk::mint: Payment received amount in quote unit sat 1 2025-10-07T12:16:24.194355Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s53: SELECT payment_id FROM mint_quote_payments WHERE payment_id = $1 FOR UPDATE 2025-10-07T12:16:24.194433Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s53 with parameters: [Text("81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b")] 2025-10-07T12:16:24.194537Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s54: SELECT amount_paid FROM mint_quote WHERE id = $1 FOR UPDATE 2025-10-07T12:16:24.194594Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s54 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")] 2025-10-07T12:16:24.194672Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: cdk_sql_common::mint: Mint quote 44633f4e-8c1f-4ed0-877a-e4d479f33cf5 amount paid was 0 is now 1. 2025-10-07T12:16:24.194683Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s55: UPDATE mint_quote SET amount_paid = $1 WHERE id = $2 2025-10-07T12:16:24.194736Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s55 with parameters: [Integer(1), Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")] 2025-10-07T12:16:24.194887Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s56: INSERT INTO mint_quote_payments (quote_id, payment_id, amount, timestamp) VALUES ( $1 , $2 , $3 , $4 ) 2025-10-07T12:16:24.194954Z DEBUG wait_for_processor_payments:handle_payment_notification:handle_mint_quote_payment:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s56 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5"), Text("81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"), Integer(1), Integer(1759839384)] 2025-10-07T12:16:24.195218Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::prepare: preparing query s57: COMMIT 2025-10-07T12:16:24.195277Z DEBUG wait_for_processor_payments:handle_payment_notification: tokio_postgres::query: executing statement s57 with parameters: [] 2025-10-07T12:16:24.198507Z DEBUG get_mint_info:mint_info: tokio_postgres::prepare: preparing query s58: SELECT value FROM kv_store WHERE primary_namespace = $1 AND secondary_namespace = $2 AND key = $3 2025-10-07T12:16:24.199036Z DEBUG get_mint_info:mint_info: tokio_postgres::query: executing statement s58 with parameters: [Text("cdk_mint"), Text("config"), Text("mint_info")] 2025-10-07T12:16:24.200738Z DEBUG get_mint_info:mint_info: tokio_postgres::prepare: preparing query s59: SELECT value FROM kv_store WHERE primary_namespace = $1 AND secondary_namespace = $2 AND key = $3 2025-10-07T12:16:24.200808Z DEBUG get_mint_info:mint_info: tokio_postgres::query: executing statement s59 with parameters: [Text("cdk_mint"), Text("config"), Text("mint_info")] 2025-10-07T12:16:24.202064Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::prepare: preparing query s60: SELECT payment_id, timestamp, amount FROM mint_quote_payments WHERE quote_id= $1 2025-10-07T12:16:24.202239Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::query: executing statement s60 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")] 2025-10-07T12:16:24.202431Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::prepare: preparing query s61: SELECT amount, timestamp FROM mint_quote_issued WHERE quote_id= $1 2025-10-07T12:16:24.202518Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::query: executing statement s61 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")] 2025-10-07T12:16:24.202639Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::prepare: preparing query s62: SELECT id, amount, unit, request, expiry, request_lookup_id, pubkey, created_time, amount_paid, amount_issued, payment_method, request_lookup_id_kind FROM mint_quote WHERE id = $1 2025-10-07T12:16:24.202755Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request: tokio_postgres::query: executing statement s62 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")] 2025-10-07T12:16:24.202985Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:check_incoming_payment_status{payment_identifier=PaymentHash([129, 97, 145, 57, 32, 95, 21, 253, 30, 10, 60, 225, 28, 106, 58, 144, 3, 36, 39, 101, 77, 235, 100, 45, 50, 58, 230, 118, 186, 138, 127, 59])}: cln_rpc: Connecting to socket at /home/bitcoin/.lightning/bitcoin/lightning-rpc 2025-10-07T12:16:24.203758Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid: tokio_postgres::prepare: preparing query s63: START TRANSACTION 2025-10-07T12:16:24.203807Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid: tokio_postgres::query: executing statement s63 with parameters: [] 2025-10-07T12:16:24.203843Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid: cdk::mint::ln: Found payment of 1000 msat for quote 44633f4e-8c1f-4ed0-877a-e4d479f33cf5 when checking. 2025-10-07T12:16:24.203861Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s64: SELECT payment_id FROM mint_quote_payments WHERE payment_id = $1 FOR UPDATE 2025-10-07T12:16:24.203925Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s64 with parameters: [Text("81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b")] 2025-10-07T12:16:24.204011Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s65: SELECT amount_paid FROM mint_quote WHERE id = $1 FOR UPDATE 2025-10-07T12:16:24.204069Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s65 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")] 2025-10-07T12:16:24.219711Z WARN wait_for_processor_payments:handle_payment_notification: cdk_sql_common::common: [SLOW QUERY] Took 24 ms: COMMIT 2025-10-07T12:16:24.219725Z DEBUG wait_for_processor_payments: cdk_cln: CLN: Stream is now active, waiting for invoice events with lastpay_index: Some(4292) 2025-10-07T12:16:24.219766Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: cdk_sql_common::mint: Mint quote 44633f4e-8c1f-4ed0-877a-e4d479f33cf5 amount paid was 1 is now 2. 2025-10-07T12:16:24.219779Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s66: UPDATE mint_quote SET amount_paid = $1 WHERE id = $2 2025-10-07T12:16:24.219871Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s66 with parameters: [Integer(2), Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5")] 2025-10-07T12:16:24.220163Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::prepare: preparing query s67: INSERT INTO mint_quote_payments (quote_id, payment_id, amount, timestamp) VALUES ( $1 , $2 , $3 , $4 ) 2025-10-07T12:16:24.220267Z DEBUG post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: tokio_postgres::query: executing statement s67 with parameters: [Text("44633f4e-8c1f-4ed0-877a-e4d479f33cf5"), Text("81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"), Integer(1), Integer(1759839384)] 2025-10-07T12:16:24.220503Z ERROR post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: cdk_sql_common::common: Query INSERT INTO mint_quote_payments (quote_id, payment_id, amount, timestamp) VALUES ( $1 , $2 , $3 , $4 ) failed with error Error { kind: Db, cause: Some(DbError { severity: "ERROR", parsed_severity: Some(Error), code: SqlState(E23505), message: "duplicate key value violates unique constraint \"mint_quote_payments_payment_id_key\"", detail: Some("Key (payment_id)=(81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b) already exists."), hint: None, position: None, where_: None, schema: Some("public"), table: Some("mint_quote_payments"), column: None, datatype: None, constraint: Some("mint_quote_payments_payment_id_key"), file: Some("nbtinsert.c"), line: Some(666), routine: Some("_bt_check_unique") }) } 2025-10-07T12:16:24.220528Z ERROR post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}:process_mint_request:check_mint_quote_paid:increment_mint_quote_amount_paid{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5) amount_paid=Amount(1) payment_id="81619139205f15fd1e0a3ce11c6a3a90032427654deb642d323ae676ba8a7f3b"}: cdk_sql_common::mint: SQLite could not insert payment ID: Duplicate entry 2025-10-07T12:16:24.220544Z ERROR post_mint_bolt11{quote_id=UUID(44633f4e-8c1f-4ed0-877a-e4d479f33cf5)}: cdk_axum::router_handlers: Could not process mint: Duplicate entry 2025-10-07T12:16:24.220564Z ERROR tower_http::trace::on_failure: response failed classification=Status code: 500 Internal Server Error latency=18 ms 2025-10-07T12:16:24.220618Z DEBUG tokio_postgres::prepare: preparing query s68: ROLLBACK 2025-10-07T12:16:24.220663Z DEBUG tokio_postgres::query: executing statement s68 with parameters: [] 2025-10-07T12:16:24.220825Z DEBUG tungstenite::protocol: Received close frame: None 2025-10-07T12:16:24.220832Z DEBUG tungstenite::protocol: Replying to close with Frame { header: FrameHeader { is_final: true, rsv1: false, rsv2: false, rsv3: false, opcode: Control(Close), mask: None }, payload: b"" } 2025-10-07T12:16:24.220839Z INFO cdk_axum::ws: ws-close: no frame 2025-10-07T12:16:24.220845Z DEBUG tokio_tungstenite: websocket start_send error: WebSocket protocol error: Sending after closing is not allowed ```
crodas commented 2025-10-08 00:09:20 +00:00 (Migrated from github.com)

Hi @daywalker90 ! Thanks for such a detailed report. I appreciate the logs. Would you mind checking if #1166 is enough to fix this race condition?

Hi @daywalker90 ! Thanks for such a detailed report. I appreciate the logs. Would you mind checking if #1166 is enough to fix this race condition?
thesimplekid commented 2025-10-08 09:07:31 +00:00 (Migrated from github.com)

Also you should still be able to mint the ecash with cdk-cli mint <mint_url> --quote-id 44633f4e-8c1f-4ed0-877a-e4d479f33cf5. Even if you got an error from the first request.

Also you should still be able to mint the ecash with `cdk-cli mint <mint_url> --quote-id 44633f4e-8c1f-4ed0-877a-e4d479f33cf5`. Even if you got an error from the first request.
daywalker90 commented 2025-10-08 11:21:04 +00:00 (Migrated from github.com)

Also you should still be able to mint the ecash with cdk-cli mint <mint_url> --quote-id 44633f4e-8c1f-4ed0-877a-e4d479f33cf5. Even if you got an error from the first request.

Yes that works but i didn't know where to get the quote-id besides from the logs.

Hi @daywalker90 ! Thanks for such a detailed report. I appreciate the logs. Would you mind checking if #1166 is enough to fix this race condition?

Everything is fixed except the command not returning when using --method bolt12 (it does with bolt11 now)

> Also you should still be able to mint the ecash with `cdk-cli mint <mint_url> --quote-id 44633f4e-8c1f-4ed0-877a-e4d479f33cf5`. Even if you got an error from the first request. Yes that works but i didn't know where to get the quote-id besides from the logs. > Hi [@daywalker90](https://github.com/daywalker90) ! Thanks for such a detailed report. I appreciate the logs. Would you mind checking if [#1166](https://github.com/cashubtc/cdk/pull/1166) is enough to fix this race condition? Everything is fixed except the command not returning when using `--method bolt12` (it does with bolt11 now)
daywalker90 commented 2025-10-08 11:23:47 +00:00 (Migrated from github.com)

These are logs of cdk-cli when i use bolt12 where everything worked in the background atleast according to balance but the command won't return to the console and i have to ctrl+c:

Please pay: lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq
2025-10-08T11:19:26.854656Z DEBUG cdk_cli::sub_commands::mint: Attempting mint for: bolt12
2025-10-08T11:19:26.855228Z DEBUG cdk::wallet::subscription: Connect to MintUrl("http://192.168.0.10:8085") to subscribe. WebSocket is supported (true)
2025-10-08T11:19:26.855364Z DEBUG cdk::wallet::subscription::ws: Connecting to ws://192.168.0.10:8085/v1/ws
2025-10-08T11:19:26.855549Z DEBUG tungstenite::handshake::client: Client handshake done.
2025-10-08T11:19:26.855574Z DEBUG cdk::wallet::subscription::ws: Connected to ws://192.168.0.10:8085/v1/ws
2025-10-08T11:19:26.855639Z DEBUG cdk::wallet::subscription::ws: Subscribing to Params { kind: Bolt12MintQuote, filters: ["90c649ac-eef8-4690-902d-cb541af49414"], id: SubId("2ZY0EdjC87") }
2025-10-08T11:19:26.855711Z DEBUG cdk::wallet::subscription::ws: Received response from server: WsResponse { jsonrpc: "2.0", result: Subscribe(WsSubscribeResponse { status: "OK", sub_id: SubId("2ZY0EdjC87") }), id: 0 }
2025-10-08T11:19:26.901832Z DEBUG cdk::wallet::subscription::ws: Received notification from server: WsNotification { jsonrpc: "2.0", method: "subscribe", params: NotificationInner { sub_id: SubId("2ZY0EdjC87"), payload: MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(0), amount_issued: Amount(0) }) } }
2025-10-08T11:19:26.901867Z DEBUG cdk::wallet::streams::payment: Receive payment notification Some(MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(0), amount_issued: Amount(0) }))
2025-10-08T11:19:34.297246Z DEBUG cdk::wallet::subscription::ws: Received notification from server: WsNotification { jsonrpc: "2.0", method: "subscribe", params: NotificationInner { sub_id: SubId("2ZY0EdjC87"), payload: MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(1), amount_issued: Amount(0) }) } }
2025-10-08T11:19:34.297286Z DEBUG cdk::wallet::streams::payment: Receive payment notification Some(MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(1), amount_issued: Amount(0) }))
2025-10-08T11:19:34.297302Z DEBUG cdk::wallet::streams::proof: Received payment (Some(Amount(1))) notification for 90c649ac-eef8-4690-902d-cb541af49414. Minting...
2025-10-08T11:19:34.297325Z DEBUG mint_bolt12{quote_id="90c649ac-eef8-4690-902d-cb541af49414" amount=Some(Amount(1)) amount_split_target=None spending_conditions=None}:refresh_keysets: cdk::wallet::keysets: Refreshing keysets and ensuring we have keys
2025-10-08T11:19:34.298418Z DEBUG mint_bolt12{quote_id="90c649ac-eef8-4690-902d-cb541af49414" amount=Some(Amount(1)) amount_split_target=None spending_conditions=None}:fetch_active_keyset:refresh_keysets: cdk::wallet::keysets: Refreshing keysets and ensuring we have keys
2025-10-08T11:19:34.299179Z DEBUG mint_bolt12{quote_id="90c649ac-eef8-4690-902d-cb541af49414" amount=Some(Amount(1)) amount_split_target=None spending_conditions=None}: cdk::wallet::issue::issue_bolt12: Incrementing keyset 007278559676d873 counter by 1
2025-10-08T11:19:34.350043Z DEBUG cdk::wallet::subscription::ws: Received notification from server: WsNotification { jsonrpc: "2.0", method: "subscribe", params: NotificationInner { sub_id: SubId("2ZY0EdjC87"), payload: MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(1), amount_issued: Amount(1) }) } }
2025-10-08T11:19:34.350837Z DEBUG cdk::wallet::streams::payment: Receive payment notification Some(MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(1), amount_issued: Amount(1) }))
These are logs of cdk-cli when i use bolt12 where everything worked in the background atleast according to `balance` but the command won't return to the console and i have to ctrl+c: ``` Please pay: lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq 2025-10-08T11:19:26.854656Z DEBUG cdk_cli::sub_commands::mint: Attempting mint for: bolt12 2025-10-08T11:19:26.855228Z DEBUG cdk::wallet::subscription: Connect to MintUrl("http://192.168.0.10:8085") to subscribe. WebSocket is supported (true) 2025-10-08T11:19:26.855364Z DEBUG cdk::wallet::subscription::ws: Connecting to ws://192.168.0.10:8085/v1/ws 2025-10-08T11:19:26.855549Z DEBUG tungstenite::handshake::client: Client handshake done. 2025-10-08T11:19:26.855574Z DEBUG cdk::wallet::subscription::ws: Connected to ws://192.168.0.10:8085/v1/ws 2025-10-08T11:19:26.855639Z DEBUG cdk::wallet::subscription::ws: Subscribing to Params { kind: Bolt12MintQuote, filters: ["90c649ac-eef8-4690-902d-cb541af49414"], id: SubId("2ZY0EdjC87") } 2025-10-08T11:19:26.855711Z DEBUG cdk::wallet::subscription::ws: Received response from server: WsResponse { jsonrpc: "2.0", result: Subscribe(WsSubscribeResponse { status: "OK", sub_id: SubId("2ZY0EdjC87") }), id: 0 } 2025-10-08T11:19:26.901832Z DEBUG cdk::wallet::subscription::ws: Received notification from server: WsNotification { jsonrpc: "2.0", method: "subscribe", params: NotificationInner { sub_id: SubId("2ZY0EdjC87"), payload: MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(0), amount_issued: Amount(0) }) } } 2025-10-08T11:19:26.901867Z DEBUG cdk::wallet::streams::payment: Receive payment notification Some(MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(0), amount_issued: Amount(0) })) 2025-10-08T11:19:34.297246Z DEBUG cdk::wallet::subscription::ws: Received notification from server: WsNotification { jsonrpc: "2.0", method: "subscribe", params: NotificationInner { sub_id: SubId("2ZY0EdjC87"), payload: MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(1), amount_issued: Amount(0) }) } } 2025-10-08T11:19:34.297286Z DEBUG cdk::wallet::streams::payment: Receive payment notification Some(MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(1), amount_issued: Amount(0) })) 2025-10-08T11:19:34.297302Z DEBUG cdk::wallet::streams::proof: Received payment (Some(Amount(1))) notification for 90c649ac-eef8-4690-902d-cb541af49414. Minting... 2025-10-08T11:19:34.297325Z DEBUG mint_bolt12{quote_id="90c649ac-eef8-4690-902d-cb541af49414" amount=Some(Amount(1)) amount_split_target=None spending_conditions=None}:refresh_keysets: cdk::wallet::keysets: Refreshing keysets and ensuring we have keys 2025-10-08T11:19:34.298418Z DEBUG mint_bolt12{quote_id="90c649ac-eef8-4690-902d-cb541af49414" amount=Some(Amount(1)) amount_split_target=None spending_conditions=None}:fetch_active_keyset:refresh_keysets: cdk::wallet::keysets: Refreshing keysets and ensuring we have keys 2025-10-08T11:19:34.299179Z DEBUG mint_bolt12{quote_id="90c649ac-eef8-4690-902d-cb541af49414" amount=Some(Amount(1)) amount_split_target=None spending_conditions=None}: cdk::wallet::issue::issue_bolt12: Incrementing keyset 007278559676d873 counter by 1 2025-10-08T11:19:34.350043Z DEBUG cdk::wallet::subscription::ws: Received notification from server: WsNotification { jsonrpc: "2.0", method: "subscribe", params: NotificationInner { sub_id: SubId("2ZY0EdjC87"), payload: MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(1), amount_issued: Amount(1) }) } } 2025-10-08T11:19:34.350837Z DEBUG cdk::wallet::streams::payment: Receive payment notification Some(MintQuoteBolt12Response(MintQuoteBolt12Response { quote: "90c649ac-eef8-4690-902d-cb541af49414", request: "lno1pqpq86q2qqfzgwp5v3snjcfkvckkgcmrxvkngefc8qknsdfkxqkk2dnxxejkvvf4xgcrxeskyypcpmczp8l3k3kr3gmu6s8kz0ga4clt5jq6jz29n4kpgd9qu4h9mrq", amount: Some(Amount(1)), unit: Sat, expiry: Some(0), pubkey: PublicKey(0260750bf40785f6d40adcffc13c10d88694c9df4ee4774deba4c3091730032935), amount_paid: Amount(1), amount_issued: Amount(1) })) ```
thesimplekid commented 2025-10-08 11:32:05 +00:00 (Migrated from github.com)

These are logs of cdk-cli when i use bolt12 where everything worked in the background atleast according to balance but the command won't return to the console and i have to ctrl+c:

This is actually expected because bolt12 is repayable so it keeps the connection open to wait for more payments. We should add print logging to make this more clear.

> These are logs of cdk-cli when i use bolt12 where everything worked in the background atleast according to balance but the command won't return to the console and i have to ctrl+c: This is actually expected because bolt12 is repayable so it keeps the connection open to wait for more payments. We should add print logging to make this more clear.
thesimplekid commented 2025-10-08 11:32:44 +00:00 (Migrated from github.com)

Yes that works but i didn't know where to get the quote-id besides from the logs.

We should print this as well I'll check.

> Yes that works but i didn't know where to get the quote-id besides from the logs. We should print this as well I'll check.
daywalker90 commented 2025-10-08 12:10:05 +00:00 (Migrated from github.com)

Also you should still be able to mint the ecash with cdk-cli mint <mint_url> --quote-id 44633f4e-8c1f-4ed0-877a-e4d479f33cf5. Even if you got an error from the first request.

oh btw i first thought the mint-pending command was for this but it only returned Error: Not enough elements: expected 11, got 10

> Also you should still be able to mint the ecash with `cdk-cli mint <mint_url> --quote-id 44633f4e-8c1f-4ed0-877a-e4d479f33cf5`. Even if you got an error from the first request. oh btw i first thought the `mint-pending` command was for this but it only returned `Error: Not enough elements: expected 11, got 10`
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
cashubtc/cdk#1162
No description provided.