Improve logs for issue #2107 (#2108)

* Improve logs for issue #2107

* Oops

Author: tomaka

light-base/src/runtime_service.rs

@@ -66,7 +66,7 @@ use alloc::{
     vec::Vec,
 };
 use async_lock::Mutex;
-use core::{cmp, iter, mem, num::NonZero, ops, pin::Pin, time::Duration};
+use core::{cmp, fmt, iter, mem, num::NonZero, ops, pin::Pin, time::Duration};
 use derive_more::derive;
 use futures_channel::oneshot;
 use futures_lite::FutureExt as _;
@@ -449,9 +449,15 @@ pub struct SubscribeAll<TPlat: PlatformRef> {
     pub new_blocks: Subscription<TPlat>,
 }
 
-#[derive(Debug, Copy, Clone, PartialEq, Eq, PartialOrd, Ord, Hash)]
+#[derive(Copy, Clone, PartialEq, Eq, PartialOrd, Ord, Hash)]
 pub struct SubscriptionId(u64);
 
+impl fmt::Debug for SubscriptionId {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        fmt::Debug::fmt(&self.0, f)
+    }
+}
+
 pub struct Subscription<TPlat: PlatformRef> {
     subscription_id: u64,
     channel: Pin<Box<async_channel::Receiver<Notification>>>,

light-base/src/sync_service/parachain.rs

@@ -333,7 +333,8 @@ impl<TPlat: PlatformRef> ParachainBackgroundTask<TPlat> {
                         "relay-chain-new-subscription",
                         finalized_hash = HashDisplay(&header::hash_from_scale_encoded_header(
                             &relay_chain_subscribe_all.finalized_block_scale_encoded_header
-                        ))
+                        )),
+                        subscription_id = ?relay_chain_subscribe_all.new_blocks.id(),
                     );
                     log!(
                         &self.platform,

light-base/src/transactions_service.rs

@@ -537,6 +537,7 @@ async fn background_task<TPlat: PlatformRef>(
             &config.log_target,
             "reset",
             new_finalized = HashDisplay(&initial_finalized_block_hash),
+            subscription_id = ?subscribe_all.new_blocks.id(),
             dropped_transactions
         );
 
@@ -751,10 +752,6 @@ async fn background_task<TPlat: PlatformRef>(
 
             // Remove finalized blocks from the pool when possible.
             for block in worker.pending_transactions.prune_finalized_with_body() {
-                // All blocks in `pending_transactions` are pinned within the runtime service.
-                // Unpin them when they're removed.
-                subscribe_all.new_blocks.unpin_block(block.block_hash).await;
-
                 log!(
                     &worker.platform,
                     Debug,
@@ -768,6 +765,10 @@ async fn background_task<TPlat: PlatformRef>(
                         .join(", ")
                 );
 
+                // All blocks in `pending_transactions` are pinned within the runtime service.
+                // Unpin them when they're removed.
+                subscribe_all.new_blocks.unpin_block(block.block_hash).await;
+
                 debug_assert!(!block.user_data.downloading);
                 for mut tx in block.included_transactions {
                     // We assume that there's no more than 2<<32 transactions per block.
@@ -853,6 +854,14 @@ async fn background_task<TPlat: PlatformRef>(
                         worker.set_best_block(&config.log_target, &best_block_hash_if_changed);
                     }
                     for pruned in worker.pending_transactions.set_finalized_block(&hash) {
+                        log!(
+                            &worker.platform,
+                            Debug,
+                            &config.log_target,
+                            "pruned-block-discard",
+                            block = HashDisplay(&pruned.0),
+                        );
+
                         // All blocks in `pending_transactions` are pinned within the
                         // runtime service. Unpin them when they're removed.
                         subscribe_all.new_blocks.unpin_block(pruned.0).await;