lightningd: trace JSON id prefixes through sendrawtx.

First, merge the _ahf_ and non-ahf interfaces.
Second, remove the always-NULL txs->cmd field.

Then, add optional id_prefix for bitcoind_sendrawx, so if it's
triggered by a command (e.g. "withdraw") it's shown correctly in logs.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

lightningd/bitcoind.c

@@ -298,12 +298,13 @@ static void sendrawtx_callback(const char *buf, const jsmntok_t *toks,
 	tal_free(call);
 }
 
-void bitcoind_sendrawtx_ahf_(struct bitcoind *bitcoind,
+void bitcoind_sendrawtx_(struct bitcoind *bitcoind,
-			     const char *hextx,
+			 const char *id_prefix,
-			     bool allowhighfees,
+			 const char *hextx,
-			     void (*cb)(struct bitcoind *bitcoind,
+			 bool allowhighfees,
-					bool success, const char *msg, void *),
+			 void (*cb)(struct bitcoind *bitcoind,
-			     void *cb_arg)
+				    bool success, const char *msg, void *),
+			 void *cb_arg)
 {
 	struct jsonrpc_request *req;
 	struct sendrawtx_call *call = tal(bitcoind, struct sendrawtx_call);
@@ -313,8 +314,7 @@ void bitcoind_sendrawtx_ahf_(struct bitcoind *bitcoind,
 	call->cb_arg = cb_arg;
 	log_debug(bitcoind->log, "sendrawtransaction: %s", hextx);
 
-	/* FIXME: pass id_prefix from caller! */
+	req = jsonrpc_request_start(bitcoind, "sendrawtransaction", id_prefix,
-	req = jsonrpc_request_start(bitcoind, "sendrawtransaction", NULL,
 				    bitcoind->log,
 				    NULL, sendrawtx_callback,
 				    call);
@@ -324,15 +324,6 @@ void bitcoind_sendrawtx_ahf_(struct bitcoind *bitcoind,
 	bitcoin_plugin_send(bitcoind, req);
 }
 
-void bitcoind_sendrawtx_(struct bitcoind *bitcoind,
-			 const char *hextx,
-			 void (*cb)(struct bitcoind *bitcoind,
-				    bool success, const char *msg, void *),
-			 void *arg)
-{
-	return bitcoind_sendrawtx_ahf_(bitcoind, hextx, false, cb, arg);
-}
-
 /* `getrawblockbyheight`
  *
  * If no block were found at that height, will set each field to `null`.

lightningd/bitcoind.h

@@ -71,29 +71,16 @@ void bitcoind_estimate_fees_(struct bitcoind *bitcoind,
 						    const u32 *),	\
 				(arg))
 
-void bitcoind_sendrawtx_ahf_(struct bitcoind *bitcoind,
-			     const char *hextx,
-			     bool allowhighfees,
-			     void (*cb)(struct bitcoind *bitcoind,
-					bool success, const char *msg, void *),
-			     void *arg);
-#define bitcoind_sendrawtx_ahf(bitcoind_, hextx, allowhighfees, cb, arg)\
-	bitcoind_sendrawtx_ahf_((bitcoind_), (hextx),			\
-				(allowhighfees),			\
-				typesafe_cb_preargs(void, void *,	\
-						    (cb), (arg),	\
-						    struct bitcoind *,	\
-						    bool, const char *),\
-				(arg))
-
 void bitcoind_sendrawtx_(struct bitcoind *bitcoind,
+			 const char *id_prefix TAKES,
 			 const char *hextx,
+			 bool allowhighfees,
 			 void (*cb)(struct bitcoind *bitcoind,
 				    bool success, const char *msg, void *),
 			 void *arg);
-
+#define bitcoind_sendrawtx(bitcoind_, id_prefix, hextx, allowhighfees, cb, arg)	\
-#define bitcoind_sendrawtx(bitcoind_, hextx, cb, arg)			\
+	bitcoind_sendrawtx_((bitcoind_), (id_prefix), (hextx),		\
-	bitcoind_sendrawtx_((bitcoind_), (hextx),			\
+			    (allowhighfees),				\
 			    typesafe_cb_preargs(void, void *,		\
 						(cb), (arg),		\
 						struct bitcoind *,	\

lightningd/chaintopology.c

@@ -125,8 +125,8 @@ struct txs_to_broadcast {
 	/* These are hex encoded already, for bitcoind_sendrawtx */
 	const char **txs;
 
-	/* Command to complete when we're done, if and only if dev-broadcast triggered */
+	/* IDs to attach to each tx (could be NULL!) */
-	struct command *cmd;
+	const char **cmd_id;
 };
 
 /* We just sent the last entry in txs[].  Shrink and send the next last. */
@@ -141,28 +141,27 @@ static void broadcast_remainder(struct bitcoind *bitcoind,
 
 	txs->cursor++;
 	if (txs->cursor == tal_count(txs->txs)) {
-		if (txs->cmd)
-			was_pending(command_success(txs->cmd,
-						    json_stream_success(txs->cmd)));
 		tal_free(txs);
 		return;
 	}
 
 	/* Broadcast next one. */
-	bitcoind_sendrawtx(bitcoind, txs->txs[txs->cursor],
+	bitcoind_sendrawtx(bitcoind,
+			   txs->cmd_id[txs->cursor], txs->txs[txs->cursor],
+			   false,
 			   broadcast_remainder, txs);
 }
 
 /* FIXME: This is dumb.  We can group txs and avoid bothering bitcoind
  * if any one tx is in the main chain. */
-static void rebroadcast_txs(struct chain_topology *topo, struct command *cmd)
+static void rebroadcast_txs(struct chain_topology *topo)
 {
 	/* Copy txs now (peers may go away, and they own txs). */
 	struct txs_to_broadcast *txs;
 	struct outgoing_tx *otx;
 
 	txs = tal(topo, struct txs_to_broadcast);
-	txs->cmd = cmd;
+	txs->cmd_id = tal_arr(txs, const char *, 0);
 
 	/* Put any txs we want to broadcast in ->txs. */
 	txs->txs = tal_arr(txs, const char *, 0);
@@ -171,6 +170,8 @@ static void rebroadcast_txs(struct chain_topology *topo, struct command *cmd)
 			continue;
 
 		tal_arr_expand(&txs->txs, tal_strdup(txs, otx->hextx));
+		tal_arr_expand(&txs->cmd_id,
+			       otx->cmd_id ? tal_strdup(txs, otx->cmd_id) : NULL);
 	}
 
 	/* Let this do the dirty work. */
@@ -214,12 +215,12 @@ static void broadcast_done(struct bitcoind *bitcoind,
 	}
 }
 
-void broadcast_tx_ahf(struct chain_topology *topo,
+void broadcast_tx(struct chain_topology *topo,
-		      struct channel *channel, const struct bitcoin_tx *tx,
+		  struct channel *channel, const struct bitcoin_tx *tx,
-		      bool allowhighfees,
+		  const char *cmd_id, bool allowhighfees,
-		      void (*failed)(struct channel *channel,
+		  void (*failed)(struct channel *channel,
-				     bool success,
+				 bool success,
-				     const char *err))
+				 const char *err))
 {
 	/* Channel might vanish: topo owns it to start with. */
 	struct outgoing_tx *otx = tal(topo, struct outgoing_tx);
@@ -229,25 +230,22 @@ void broadcast_tx_ahf(struct chain_topology *topo,
 	bitcoin_txid(tx, &otx->txid);
 	otx->hextx = tal_hex(otx, rawtx);
 	otx->failed_or_success = failed;
+	if (cmd_id)
+		otx->cmd_id = tal_strdup(otx, cmd_id);
+	else
+		otx->cmd_id = NULL;
 	tal_free(rawtx);
 	tal_add_destructor2(channel, clear_otx_channel, otx);
 
-	log_debug(topo->log, "Broadcasting txid %s",
+	log_debug(topo->log, "Broadcasting txid %s%s%s",
-		  type_to_string(tmpctx, struct bitcoin_txid, &otx->txid));
+		  type_to_string(tmpctx, struct bitcoin_txid, &otx->txid),
+		  cmd_id ? " for " : "", cmd_id ? cmd_id : "");
 
 	wallet_transaction_add(topo->ld->wallet, tx->wtx, 0, 0);
-	bitcoind_sendrawtx_ahf(topo->bitcoind, otx->hextx, allowhighfees,
+	bitcoind_sendrawtx(topo->bitcoind, otx->cmd_id, otx->hextx,
-			       broadcast_done, otx);
+			   allowhighfees,
+			   broadcast_done, otx);
 }
-void broadcast_tx(struct chain_topology *topo,
-		  struct channel *channel, const struct bitcoin_tx *tx,
-		  void (*failed)(struct channel *channel,
-				 bool success,
-				 const char *err))
-{
-	return broadcast_tx_ahf(topo, channel, tx, false, failed);
-}
-
 
 static enum watch_result closeinfo_txid_confirmed(struct lightningd *ld,
 						  struct channel *channel,
@@ -599,7 +597,7 @@ static void updates_complete(struct chain_topology *topo)
 		notify_new_block(topo->bitcoind->ld, topo->tip->height);
 
 		/* Maybe need to rebroadcast. */
-		rebroadcast_txs(topo, NULL);
+		rebroadcast_txs(topo);
 
 		/* We've processed these UTXOs */
 		db_set_intvar(topo->bitcoind->ld->wallet->db,

lightningd/chaintopology.h

@@ -22,6 +22,7 @@ struct outgoing_tx {
 	struct channel *channel;
 	const char *hextx;
 	struct bitcoin_txid txid;
+	const char *cmd_id;
 	void (*failed_or_success)(struct channel *channel, bool success, const char *err);
 };
 
@@ -151,21 +152,21 @@ u32 delayed_to_us_feerate(struct chain_topology *topo);
 u32 htlc_resolution_feerate(struct chain_topology *topo);
 u32 penalty_feerate(struct chain_topology *topo);
 
-/* Broadcast a single tx, and rebroadcast as reqd (copies tx).
+/**
- * If failed is non-NULL, call that and don't rebroadcast. */
+ * broadcast_tx - Broadcast a single tx, and rebroadcast as reqd (copies tx).
+ * @topo: topology
+ * @channel: the channel responsible for this (stop broadcasting if freed).
+ * @tx: the transaction
+ * @cmd_id: the JSON command id which triggered this (or NULL).
+ * @allowhighfees: set to true to override the high-fee checks in the backend.
+ * @failed: if non-NULL, call that and don't rebroadcast.
+ */
 void broadcast_tx(struct chain_topology *topo,
 		  struct channel *channel, const struct bitcoin_tx *tx,
+		  const char *cmd_id, bool allowhighfees,
 		  void (*failed)(struct channel *,
 				 bool success,
 				 const char *err));
-/* Like the above, but with an additional `allowhighfees` parameter.
- * If true, suppress any high-fee checks in the backend.  */
-void broadcast_tx_ahf(struct chain_topology *topo,
-		      struct channel *channel, const struct bitcoin_tx *tx,
-		      bool allowhighfees,
-		      void (*failed)(struct channel *,
-				     bool success,
-				     const char *err));
 
 struct chain_topology *new_topology(struct lightningd *ld, struct log *log);
 void setup_topology(struct chain_topology *topology,

lightningd/channel.c

@@ -921,7 +921,8 @@ void channel_internal_error(struct channel *channel, const char *fmt, ...)
 
 	/* Don't expose internal error causes to remove unless doing dev */
 #if DEVELOPER
-	channel_fail_permanent(channel, REASON_LOCAL, "Internal error: %s", why);
+	channel_fail_permanent(channel,
+			       REASON_LOCAL, "Internal error: %s", why);
 #else
 	channel_fail_permanent(channel, REASON_LOCAL, "Internal error");
 #endif

lightningd/closing_control.c

@@ -46,6 +46,7 @@ struct close_command {
 	struct command *cmd;
 	/* Channel being closed. */
 	struct channel *channel;
+
 };
 
 /* Resolve a single close command. */
@@ -68,18 +69,24 @@ resolve_one_close_command(struct close_command *cc, bool cooperative)
 	was_pending(command_success(cc->cmd, result));
 }
 
-/* Resolve a close command for a channel that will be closed soon. */
+/* Resolve a close command for a channel that will be closed soon: returns
-void resolve_close_command(struct lightningd *ld, struct channel *channel,
+ * the cmd_id of one, if any (allocated off ctx). */
-			   bool cooperative)
+const char *resolve_close_command(const tal_t *ctx,
+				  struct lightningd *ld, struct channel *channel,
+				  bool cooperative)
 {
 	struct close_command *cc;
 	struct close_command *n;
+	const char *cmd_id = NULL;
 
 	list_for_each_safe(&ld->close_commands, cc, n, list) {
 		if (cc->channel != channel)
 			continue;
+		if (!cmd_id)
+			cmd_id = tal_strdup(ctx, cc->cmd->id);
 		resolve_one_close_command(cc, cooperative);
 	}
+	return cmd_id;
 }
 
 /* Destroy the close command structure in reaction to the

lightningd/closing_control.h

@@ -8,8 +8,11 @@ struct channel;
 struct lightningd;
 struct peer_fd;
 
-void resolve_close_command(struct lightningd *ld, struct channel *channel,
+/* Resolve a close command for a channel that will be closed soon: returns
-			   bool cooperative);
+ * the cmd_id of one, if any (allocated off ctx). */
+const char *resolve_close_command(const tal_t *ctx,
+				  struct lightningd *ld, struct channel *channel,
+				  bool cooperative);
 
 void peer_start_closingd(struct channel *channel,
 			 struct peer_fd *peer_fd);

lightningd/dual_open_control.c

@@ -1561,7 +1561,13 @@ static void send_funding_tx(struct channel *channel,
 		  type_to_string(tmpctx, struct wally_tx, cs->wtx));
 
 	bitcoind_sendrawtx(ld->topology->bitcoind,
+			   channel->open_attempt
+			   ? (channel->open_attempt->cmd
+			      ? channel->open_attempt->cmd->id
+			      : NULL)
+			   : NULL,
 			   tal_hex(tmpctx, linearize_wtx(tmpctx, cs->wtx)),
+			   false,
 			   sendfunding_done, cs);
 }
 

lightningd/jsonrpc.c

@@ -1333,6 +1333,8 @@ struct jsonrpc_request *jsonrpc_request_start_(
 				id_prefix, method, next_request_id);
 	else
 		r->id = tal_fmt(r, "cln:%s#%"PRIu64, method, next_request_id);
+	if (taken(id_prefix))
+		tal_free(id_prefix);
 	next_request_id++;
 	r->notify_cb = notify_cb;
 	r->response_cb = response_cb;

lightningd/jsonrpc.h

@@ -251,7 +251,7 @@ void jsonrpc_notification_end(struct jsonrpc_notification *n);
 
 struct jsonrpc_request *jsonrpc_request_start_(
     const tal_t *ctx, const char *method,
-    const char *id_prefix, struct log *log, bool add_header,
+    const char *id_prefix TAKES, struct log *log, bool add_header,
     void (*notify_cb)(const char *buffer,
 		      const jsmntok_t *idtok,
 		      const jsmntok_t *methodtok,

lightningd/onchain_control.c

@@ -348,9 +348,9 @@ static void handle_onchain_broadcast_tx(struct channel *channel,
 	/* If the onchaind signals this as RBF-able, then we also
 	 * set allowhighfees, as the transaction may be RBFed into
 	 * high feerates as protection against the MAD-HTLC attack.  */
-	broadcast_tx_ahf(channel->peer->ld->topology, channel,
+	broadcast_tx(channel->peer->ld->topology, channel,
-			 tx, is_rbf,
+		     tx, NULL, is_rbf,
-			 is_rbf ? &handle_onchain_broadcast_rbf_tx_cb : NULL);
+		     is_rbf ? &handle_onchain_broadcast_rbf_tx_cb : NULL);
 }
 
 static void handle_onchain_unwatch_tx(struct channel *channel, const u8 *msg)
@@ -622,7 +622,8 @@ enum watch_result onchaind_funding_spent(struct channel *channel,
 	if (channel->closer != NUM_SIDES)
 		reason = REASON_UNKNOWN;  /* will use last cause as reason */
 
-	channel_fail_permanent(channel, reason, "Funding transaction spent");
+	channel_fail_permanent(channel, reason,
+			       "Funding transaction spent");
 
 	/* If we haven't posted the open event yet, post an open */
 	if (!channel->scid || !channel->remote_channel_ready) {

lightningd/peer_control.c

@@ -271,6 +271,7 @@ bool invalid_last_tx(const struct bitcoin_tx *tx)
 
 static void sign_and_send_last(struct lightningd *ld,
 			       struct channel *channel,
+			       const char *cmd_id,
 			       struct bitcoin_tx *last_tx,
 			       struct bitcoin_signature *last_sig)
 {
@@ -285,7 +286,7 @@ static void sign_and_send_last(struct lightningd *ld,
 
 	/* Keep broadcasting until we say stop (can fail due to dup,
 	 * if they beat us to the broadcast). */
-	broadcast_tx(ld->topology, channel, last_tx, NULL);
+	broadcast_tx(ld->topology, channel, last_tx, cmd_id, false, NULL);
 
 	remove_sig(last_tx);
 }
@@ -294,6 +295,11 @@ void drop_to_chain(struct lightningd *ld, struct channel *channel,
 		   bool cooperative)
 {
 	struct channel_inflight *inflight;
+	const char *cmd_id;
+
+	/* If this was triggered by a close command, get a copy of the cmd id */
+	cmd_id = resolve_close_command(tmpctx, ld, channel, cooperative);
+
 	/* BOLT #2:
 	 *
 	 * - if `next_revocation_number` is greater than expected
@@ -313,15 +319,14 @@ void drop_to_chain(struct lightningd *ld, struct channel *channel,
 		/* We need to drop *every* commitment transaction to chain */
 		if (!cooperative && !list_empty(&channel->inflights)) {
 			list_for_each(&channel->inflights, inflight, list)
-				sign_and_send_last(ld, channel,
+				sign_and_send_last(ld, channel, cmd_id,
 						   inflight->last_tx,
 						   &inflight->last_sig);
 		} else
-			sign_and_send_last(ld, channel, channel->last_tx,
+			sign_and_send_last(ld, channel, cmd_id, channel->last_tx,
 					   &channel->last_sig);
 	}
 
-	resolve_close_command(ld, channel, cooperative);
 }
 
 void resend_closing_transactions(struct lightningd *ld)
@@ -1759,7 +1764,8 @@ static enum watch_result funding_depth_cb(struct lightningd *ld,
 		if (!list_empty(&channel->inflights)) {
 			inf = channel_inflight_find(channel, txid);
 			if (!inf) {
-				channel_fail_permanent(channel, REASON_LOCAL,
+				channel_fail_permanent(channel,
+						       REASON_LOCAL,
 					"Txid %s for channel"
 					" not found in inflights. (peer %s)",
 					type_to_string(tmpctx,

lightningd/test/run-invoice-select-inchan.c

@@ -50,6 +50,7 @@ char *bolt11_encode_(const tal_t *ctx UNNEEDED,
 /* Generated stub for broadcast_tx */
 void broadcast_tx(struct chain_topology *topo UNNEEDED,
 		  struct channel *channel UNNEEDED, const struct bitcoin_tx *tx UNNEEDED,
+		  const char *cmd_id UNNEEDED, bool allowhighfees UNNEEDED,
 		  void (*failed)(struct channel * UNNEEDED,
 				 bool success UNNEEDED,
 				 const char *err))
@@ -492,7 +493,7 @@ void jsonrpc_request_end(struct jsonrpc_request *request UNNEEDED)
 /* Generated stub for jsonrpc_request_start_ */
 struct jsonrpc_request *jsonrpc_request_start_(
     const tal_t *ctx UNNEEDED, const char *method UNNEEDED,
-    const char *id_prefix UNNEEDED, struct log *log UNNEEDED, bool add_header UNNEEDED,
+    const char *id_prefix TAKES UNNEEDED, struct log *log UNNEEDED, bool add_header UNNEEDED,
     void (*notify_cb)(const char *buffer UNNEEDED,
 		      const jsmntok_t *idtok UNNEEDED,
 		      const jsmntok_t *methodtok UNNEEDED,
@@ -681,8 +682,9 @@ void plugin_request_send(struct plugin *plugin UNNEEDED,
 void report_subd_memleak(struct leak_detect *leak_detect UNNEEDED, struct subd *leaker UNNEEDED)
 { fprintf(stderr, "report_subd_memleak called!\n"); abort(); }
 /* Generated stub for resolve_close_command */
-void resolve_close_command(struct lightningd *ld UNNEEDED, struct channel *channel UNNEEDED,
+const char *resolve_close_command(const tal_t *ctx UNNEEDED,
-			   bool cooperative UNNEEDED)
+				  struct lightningd *ld UNNEEDED, struct channel *channel UNNEEDED,
+				  bool cooperative UNNEEDED)
 { fprintf(stderr, "resolve_close_command called!\n"); abort(); }
 /* Generated stub for start_leak_request */
 void start_leak_request(const struct subd_req *req UNNEEDED,

tests/test_wallet.py

@@ -59,6 +59,9 @@ def test_withdraw(node_factory, bitcoind):
 
     out = l1.rpc.withdraw(waddr, 2 * amount)
 
+    # Side note: sendrawtransaction will trace back to withdrawl
+    l1.daemon.wait_for_log(": OUT:id=[0-9]*/cln:sendrawtransaction#[0-9]*")
+
     # Make sure bitcoind received the withdrawal
     unspent = l1.bitcoin.rpc.listunspent(0)
     withdrawal = [u for u in unspent if u['txid'] == out['txid']]

wallet/test/run-wallet.c

@@ -70,6 +70,7 @@ bool blinding_next_pubkey(const struct pubkey *pk UNNEEDED,
 /* Generated stub for broadcast_tx */
 void broadcast_tx(struct chain_topology *topo UNNEEDED,
 		  struct channel *channel UNNEEDED, const struct bitcoin_tx *tx UNNEEDED,
+		  const char *cmd_id UNNEEDED, bool allowhighfees UNNEEDED,
 		  void (*failed)(struct channel * UNNEEDED,
 				 bool success UNNEEDED,
 				 const char *err))
@@ -669,8 +670,9 @@ struct route_step *process_onionpacket(
 void report_subd_memleak(struct leak_detect *leak_detect UNNEEDED, struct subd *leaker UNNEEDED)
 { fprintf(stderr, "report_subd_memleak called!\n"); abort(); }
 /* Generated stub for resolve_close_command */
-void resolve_close_command(struct lightningd *ld UNNEEDED, struct channel *channel UNNEEDED,
+const char *resolve_close_command(const tal_t *ctx UNNEEDED,
-			   bool cooperative UNNEEDED)
+				  struct lightningd *ld UNNEEDED, struct channel *channel UNNEEDED,
+				  bool cooperative UNNEEDED)
 { fprintf(stderr, "resolve_close_command called!\n"); abort(); }
 /* Generated stub for serialize_onionpacket */
 u8 *serialize_onionpacket(

wallet/walletrpc.c

@@ -898,7 +898,7 @@ static void sendpsbt_done(struct bitcoind *bitcoind UNUSED,
 
 static struct command_result *json_sendpsbt(struct command *cmd,
 					    const char *buffer,
-					    const jsmntok_t *obj UNNEEDED,
+					    const jsmntok_t *obj,
 					    const jsmntok_t *params)
 {
 	struct command_result *res;
@@ -947,9 +947,10 @@ static struct command_result *json_sendpsbt(struct command *cmd,
 
 	/* Now broadcast the transaction */
 	bitcoind_sendrawtx(cmd->ld->topology->bitcoind,
+			   cmd->id,
 			   tal_hex(tmpctx,
 				   linearize_wtx(tmpctx, sending->wtx)),
-			   sendpsbt_done, sending);
+			   false, sendpsbt_done, sending);
 
 	return command_still_pending(cmd);
 }